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
- config_660-van_g4 [application/octet-stream] 113920 bytes
- dmesg_660_g4_09 [application/octet-stream] 72390 bytes