Recurring data races when machine at idle e.g. "BUG: KCSAN: data-race in tick_nohz_idle_stop_tick / tick_sched_do_timer" and several data races at boot (G4 DP, kernel v6.6)

From: Erhard Furtner <hidden>
Date: 2023-11-06 21:53:56

Greetings!

I did a test run with kernel v6.6 on my G4 DP with KCSAN_EARLY_ENABLE=y, KCSAN_REPORT_ONCE_IN_MS=12000, KCSAN_STRICT=y, KCSAN_WEAK_MEMORY=y, CONFIG_KCSAN_VERBOSE=y hoping to get some hints about what might cause https://bugzilla.kernel.org/show_bug.cgi?id=215389 The G4 was operated and also output was gathered via serial console.

When the G4 has finished booting and is idle I get races like these every few minutes, sometimes more often without even using the machine:
==================================================================
BUG: KCSAN: data-race in tick_nohz_idle_stop_tick / tick_sched_do_timer

write to 0xc1a3f0c4 of 4 bytes by interrupt on cpu 1:
 tick_sched_do_timer+0x170/0x1c0
 tick_sched_timer+0x88/0x224
 __hrtimer_run_queues+0x5d8/0x7d4
 hrtimer_interrupt+0x234/0x4d8
 timer_interrupt+0xec/0x24c
 Decrementer_virt+0x108/0x10c
 default_idle_call+0x13c/0x274
 do_idle+0x100/0x188
 cpu_startup_entry+0x34/0x38
 start_secondary+0x5ac/0xb58
 0x3334

no locks held by swapper/1/0.
irq event stamp: 148094222
hardirqs last  enabled at (148094221): [<c12fe03c>] default_idle_call+0x13c/0x274
hardirqs last disabled at (148094222): [<c00156a0>] interrupt_async_enter_prepare+0xf0/0x138
softirqs last  enabled at (147912796): [<c13107a0>] __do_softirq+0x490/0x4f8
softirqs last disabled at (147912785): [<c000c658>] do_softirq_own_stack+0x58/0xa4

read to 0xc1a3f0c4 of 4 bytes by task 0 on cpu 0:
 tick_nohz_idle_stop_tick+0x1f0/0x6f4
 do_idle+0xfc/0x188
 cpu_startup_entry+0x34/0x38
 rest_init+0x184/0x24c
 arch_post_acpi_subsys_init+0x0/0xc
 console_on_rootfs+0x0/0x98
 0x3610

no locks held by swapper/0/0.
irq event stamp: 149549446
hardirqs last  enabled at (149549445): [<c12fe03c>] default_idle_call+0x13c/0x274
hardirqs last disabled at (149549446): [<c011591c>] do_idle+0xd0/0x188
softirqs last  enabled at (149492862): [<c13107a0>] __do_softirq+0x490/0x4f8
softirqs last disabled at (149492845): [<c000c658>] do_softirq_own_stack+0x58/0xa4

Reported by Kernel Concurrency Sanitizer on:
CPU: 0 PID: 0 Comm: swapper/0 Not tainted 6.6.0-PMacG4-dirty #19
Hardware name: PowerMac3,6 7455 0x80010303 PowerMac
==================================================================


Also I get "BUG: KCSAN: data-race in tick_nohz_idle_stop_tick / tick_nohz_next_event" and "BUG: KCSAN: data-race in tick_nohz_next_event / tick_sched_do_timer" frequently when not actively using the machine (see dmesg).

During boot I regularly get rcu related races like this:
==================================================================
BUG: KCSAN: data-race in rcu_all_qs / rcu_disable_urgency_upon_qs

write (marked) to 0xeedc7805 of 1 bytes by interrupt on cpu 1:
 rcu_disable_urgency_upon_qs+0x4c/0x10c
 rcu_report_qs_rdp+0x490/0x4e0
 rcu_core+0x810/0xe74
 rcu_core_si+0x20/0x48
 __do_softirq+0x16c/0x4f8
 do_softirq_own_stack+0x58/0xa4
 ct_irq_enter+0x9c/0xc0
 __irq_exit_rcu+0x148/0x184
 irq_exit+0x10/0x60
 interrupt_async_exit_prepare.isra.0+0x18/0x34
 timer_interrupt+0x124/0x24c
 Decrementer_virt+0x108/0x10c
 0xeedc7805
 0x0
 rcu_all_qs+0x6c/0x268
 __cond_resched+0x1c/0x7c
 __kmem_cache_alloc_node+0x324/0x4a4
 kmalloc_trace+0x40/0x150
 ttm_range_man_alloc+0xc0/0x224 [ttm]
 ttm_resource_alloc+0x9c/0x124 [ttm]
 ttm_bo_mem_space+0x114/0x3a4 [ttm]
 ttm_bo_validate+0x108/0x39c [ttm]
 ttm_bo_init_reserved+0x2c8/0x310 [ttm]
 ttm_bo_init_validate+0xb4/0x1cc [ttm]
 radeon_bo_create+0x220/0x3ec [radeon]
 radeon_gem_object_create+0xe4/0x2dc [radeon]
 radeon_gem_create_ioctl+0xd4/0x20c [radeon]
 drm_ioctl_kernel+0x150/0x270
 drm_ioctl+0x328/0x6d0
 radeon_drm_ioctl+0x94/0x174 [radeon]
 sys_ioctl+0x338/0x1144
 system_call_exception+0x10c/0x1f0
 ret_from_syscall+0x0/0x2c

read to 0xeedc7805 of 1 bytes by task 331 on cpu 1:
 rcu_all_qs+0x6c/0x268
 __cond_resched+0x1c/0x7c
 __kmem_cache_alloc_node+0x324/0x4a4
 kmalloc_trace+0x40/0x150
 ttm_range_man_alloc+0xc0/0x224 [ttm]
 ttm_resource_alloc+0x9c/0x124 [ttm]
 ttm_bo_mem_space+0x114/0x3a4 [ttm]
 ttm_bo_validate+0x108/0x39c [ttm]
 ttm_bo_init_reserved+0x2c8/0x310 [ttm]
 ttm_bo_init_validate+0xb4/0x1cc [ttm]
 radeon_bo_create+0x220/0x3ec [radeon]
 radeon_gem_object_create+0xe4/0x2dc [radeon]
 radeon_gem_create_ioctl+0xd4/0x20c [radeon]
 drm_ioctl_kernel+0x150/0x270
 drm_ioctl+0x328/0x6d0
 radeon_drm_ioctl+0x94/0x174 [radeon]
 sys_ioctl+0x338/0x1144
 system_call_exception+0x10c/0x1f0
 ret_from_syscall+0x0/0x2c

3 locks held by X/331:
 #0: c5ac004c (&rdev->exclusive_lock){.+.+}-{3:3}, at: radeon_gem_create_ioctl+0x68/0x20c [radeon]
 #1: c5ac1ea8 (&rdev->pm.mclk_lock){.+.+}-{3:3}, at: radeon_bo_create+0x1f0/0x3ec [radeon]
 #2: c7b4855c (reservation_ww_class_mutex){+.+.}-{3:3}, at: ww_mutex_trylock+0x22c/0x53c
irq event stamp: 483150
hardirqs last  enabled at (483149): [<c017df18>] note_gp_changes+0x2b4/0x2e4
hardirqs last disabled at (483150): [<c130ee58>] _raw_spin_lock_irqsave+0xd8/0xdc
softirqs last  enabled at (482937): [<c13107a0>] __do_softirq+0x490/0x4f8
softirqs last disabled at (483144): [<c000c658>] do_softirq_own_stack+0x58/0xa4

Reported by Kernel Concurrency Sanitizer on:
CPU: 1 PID: 331 Comm: X Not tainted 6.6.0-PMacG4-dirty #19
Hardware name: PowerMac3,6 7455 0x80010303 PowerMac
==================================================================


This one also occurs most of the time:
==================================================================
BUG: KCSAN: data-race in copyout / interrupt_async_enter_prepare

read to 0xc26420dc of 4 bytes by task 1 on cpu 1:
 interrupt_async_enter_prepare+0x78/0x138
 do_IRQ+0x18/0x40
 HardwareInterrupt_virt+0x108/0x10c
 0xc26420dc
 0xa9041d9f
 copyout+0x64/0x130
 _copy_to_iter+0xc8/0x894
 get_random_bytes_user+0x23c/0x260
 sys_getrandom+0xd0/0x16c
 system_call_exception+0x10c/0x1f0
 ret_from_syscall+0x0/0x2c

write to 0xc26420dc of 4 bytes by task 1 on cpu 1:
 copyout+0x64/0x130
 _copy_to_iter+0xc8/0x894
 get_random_bytes_user+0x23c/0x260
 sys_getrandom+0xd0/0x16c
 system_call_exception+0x10c/0x1f0
 ret_from_syscall+0x0/0x2c

no locks held by systemd/1.
irq event stamp: 1056783
hardirqs last  enabled at (1056782): [<c0c095c0>] crng_make_state+0x2f8/0x490
hardirqs last disabled at (1056783): [<c000bc80>] interrupt_async_enter_prepare+0xf0/0x138
softirqs last  enabled at (1056741): [<c13107a0>] __do_softirq+0x490/0x4f8
softirqs last disabled at (1056712): [<c000c658>] do_softirq_own_stack+0x58/0xa4

Reported by Kernel Concurrency Sanitizer on:
CPU: 1 PID: 1 Comm: systemd Not tainted 6.6.0-PMacG4-dirty #19
Hardware name: PowerMac3,6 7455 0x80010303 PowerMac
==================================================================

Some data about the G4 DP:
0000:00:0b.0 Host bridge: Apple Inc. UniNorth 2 AGP
0000:00:10.0 VGA compatible controller: Advanced Micro Devices, Inc. [AMD/ATI] RV350 [Radeon 9550/9600/X1050 Series]
0001:00:0b.0 Host bridge: Apple Inc. UniNorth 2 PCI
0001:00:12.0 USB controller: NEC Corporation OHCI USB Controller (rev 43)
0001:00:12.1 USB controller: NEC Corporation OHCI USB Controller (rev 43)
0001:00:12.2 USB controller: NEC Corporation uPD72010x USB 2.0 Controller (rev 04)
0001:00:13.0 Mass storage controller: Silicon Image, Inc. SiI 3112 [SATALink/SATARaid] Serial ATA Controller (rev 02)
0001:00:15.0 Serial controller: MosChip Semiconductor Technology Ltd. PCI 9865 Multi-I/O Controller
0001:00:15.1 Serial controller: MosChip Semiconductor Technology Ltd. PCI 9865 Multi-I/O Controller
0001:00:15.2 Parallel controller: Illegal Vendor ID Device 9865
0001:00:16.0 Network controller: Broadcom Inc. and subsidiaries BCM4306 802.11b/g Wireless LAN Controller (rev 02)
0001:00:17.0 Unassigned class [ff00]: Apple Inc. KeyLargo Mac I/O (rev 03)
0001:00:18.0 USB controller: Apple Inc. KeyLargo USB
0001:00:19.0 USB controller: Apple Inc. KeyLargo USB
0001:00:1b.0 USB controller: NEC Corporation OHCI USB Controller (rev 43)
0001:00:1b.1 USB controller: NEC Corporation OHCI USB Controller (rev 43)
0001:00:1b.2 USB controller: NEC Corporation uPD72010x USB 2.0 Controller (rev 04)
0002:00:0b.0 Host bridge: Apple Inc. UniNorth 2 Internal PCI
0002:00:0d.0 Unassigned class [ff00]: Apple Inc. UniNorth 2 ATA/100
0002:00:0e.0 FireWire (IEEE 1394): Apple Inc. UniNorth 2 FireWire (rev 01)
0002:00:0f.0 Ethernet controller: Apple Inc. UniNorth 2 GMAC (Sun GEM)

Please find full dmesg and 6.6 kernel .config attached.

Regards,
Erhard

Attachments

Keyboard shortcuts
hback out one level
jnext message in thread
kprevious message in thread
ldrill in
Escclose help / fold thread tree
?toggle this help