[BUG] KCSAN: data-race in process_one_work / process_one_work

[BUG] KCSAN: data-race in process_one_work / process_one_work

[Mirsad Todorovac]

[-- Attachment #1: Type: text/plain, Size: 1679 bytes --]

Hi,

This is your friendly bug reporter.

The environment is vanilla torvalds tree kernel on Ubuntu 22.04 LTS and on a Ryzen 7950X
assembled box.

The kernel reports G taint "properietary module loaded", but I know of no module since
the boot state when the status was "Not tainted".

Please find the complete dmesg output (or what's left in the ring buffer) and lshw output
attached.

Here is the dmesg output excerpt:

[ 6849.221584] ==================================================================
[ 6849.221607] BUG: KCSAN: data-race in process_one_work / process_one_work

[ 6849.221635] write to 0xffff9b7440151398 of 8 bytes by task 6364 on cpu 7:
[ 6849.221647]  process_one_work+0x504/0x930
[ 6849.221660]  worker_thread+0x311/0x7e0
[ 6849.221673]  kthread+0x18b/0x1d0
[ 6849.221683]  ret_from_fork+0x43/0x70
[ 6849.221695]  ret_from_fork_asm+0x1b/0x30

[ 6849.221712] read to 0xffff9b7440151398 of 8 bytes by task 5586 on cpu 28:
[ 6849.221724]  process_one_work+0x4e8/0x930
[ 6849.221737]  worker_thread+0x519/0x7e0
[ 6849.221749]  kthread+0x18b/0x1d0
[ 6849.221759]  ret_from_fork+0x43/0x70
[ 6849.221770]  ret_from_fork_asm+0x1b/0x30

[ 6849.221786] value changed: 0x00000000000154d0 -> 0x00000000000154d1

[ 6849.221802] Reported by Kernel Concurrency Sanitizer on:
[ 6849.221811] CPU: 28 PID: 5586 Comm: kworker/u64:0 Tainted: G             L     6.5.0-rc6-net-cfg-kcsan-00038-g16931859a650 #35
[ 6849.221825] Hardware name: ASRock X670E PG Lightning/X670E PG Lightning, BIOS 1.21 04/26/2023
[ 6849.221833] Workqueue: events_unbound wq_barrier_func
[ 6849.221846] ==================================================================

Best regards,
Mirsad Todorovac

[-- Attachment #2: dmesg-3.log.xz --]
[-- Type: application/x-xz, Size: 67080 bytes --]

[-- Attachment #3: lshw.txt.xz --]
[-- Type: application/x-xz, Size: 6516 bytes --]

Re: [BUG] KCSAN: data-race in process_one_work / process_one_work

[Tejun Heo]

On Thu, Aug 17, 2023 at 09:24:28PM +0200, Mirsad Todorovac wrote:
> Hi,
> 
> This is your friendly bug reporter.
> 
> The environment is vanilla torvalds tree kernel on Ubuntu 22.04 LTS and on a Ryzen 7950X
> assembled box.
> 
> The kernel reports G taint "properietary module loaded", but I know of no module since
> the boot state when the status was "Not tainted".
> 
> Please find the complete dmesg output (or what's left in the ring buffer) and lshw output
> attached.
> 
> Here is the dmesg output excerpt:
> 
> [ 6849.221584] ==================================================================
> [ 6849.221607] BUG: KCSAN: data-race in process_one_work / process_one_work
> 
> [ 6849.221635] write to 0xffff9b7440151398 of 8 bytes by task 6364 on cpu 7:
> [ 6849.221647]  process_one_work+0x504/0x930
> [ 6849.221660]  worker_thread+0x311/0x7e0
> [ 6849.221673]  kthread+0x18b/0x1d0
> [ 6849.221683]  ret_from_fork+0x43/0x70
> [ 6849.221695]  ret_from_fork_asm+0x1b/0x30
> 
> [ 6849.221712] read to 0xffff9b7440151398 of 8 bytes by task 5586 on cpu 28:
> [ 6849.221724]  process_one_work+0x4e8/0x930
> [ 6849.221737]  worker_thread+0x519/0x7e0
> [ 6849.221749]  kthread+0x18b/0x1d0
> [ 6849.221759]  ret_from_fork+0x43/0x70
> [ 6849.221770]  ret_from_fork_asm+0x1b/0x30
> 
> [ 6849.221786] value changed: 0x00000000000154d0 -> 0x00000000000154d1
> 
> [ 6849.221802] Reported by Kernel Concurrency Sanitizer on:
> [ 6849.221811] CPU: 28 PID: 5586 Comm: kworker/u64:0 Tainted: G             L     6.5.0-rc6-net-cfg-kcsan-00038-g16931859a650 #35
> [ 6849.221825] Hardware name: ASRock X670E PG Lightning/X670E PG Lightning, BIOS 1.21 04/26/2023
> [ 6849.221833] Workqueue: events_unbound wq_barrier_func
> [ 6849.221846] ==================================================================

That looks like the PENDING bit. The setting is atomic. Maybe there's a raw
read? Can you map the addresses to lines?

Thanks.

-- 
tejun

Re: [BUG] KCSAN: data-race in process_one_work / process_one_work

[Mirsad Todorovac]

On 8/17/23 23:59, Tejun Heo wrote:
> On Thu, Aug 17, 2023 at 09:24:28PM +0200, Mirsad Todorovac wrote:
>> Hi,
>>
>> This is your friendly bug reporter.
>>
>> The environment is vanilla torvalds tree kernel on Ubuntu 22.04 LTS and on a Ryzen 7950X
>> assembled box.
>>
>> The kernel reports G taint "properietary module loaded", but I know of no module since
>> the boot state when the status was "Not tainted".
>>
>> Please find the complete dmesg output (or what's left in the ring buffer) and lshw output
>> attached.
>>
>> Here is the dmesg output excerpt:
>>
>> [ 6849.221584] ==================================================================
>> [ 6849.221607] BUG: KCSAN: data-race in process_one_work / process_one_work
>>
>> [ 6849.221635] write to 0xffff9b7440151398 of 8 bytes by task 6364 on cpu 7:
>> [ 6849.221647]  process_one_work+0x504/0x930
>> [ 6849.221660]  worker_thread+0x311/0x7e0
>> [ 6849.221673]  kthread+0x18b/0x1d0
>> [ 6849.221683]  ret_from_fork+0x43/0x70
>> [ 6849.221695]  ret_from_fork_asm+0x1b/0x30
>>
>> [ 6849.221712] read to 0xffff9b7440151398 of 8 bytes by task 5586 on cpu 28:
>> [ 6849.221724]  process_one_work+0x4e8/0x930
>> [ 6849.221737]  worker_thread+0x519/0x7e0
>> [ 6849.221749]  kthread+0x18b/0x1d0
>> [ 6849.221759]  ret_from_fork+0x43/0x70
>> [ 6849.221770]  ret_from_fork_asm+0x1b/0x30
>>
>> [ 6849.221786] value changed: 0x00000000000154d0 -> 0x00000000000154d1
>>
>> [ 6849.221802] Reported by Kernel Concurrency Sanitizer on:
>> [ 6849.221811] CPU: 28 PID: 5586 Comm: kworker/u64:0 Tainted: G             L     6.5.0-rc6-net-cfg-kcsan-00038-g16931859a650 #35
>> [ 6849.221825] Hardware name: ASRock X670E PG Lightning/X670E PG Lightning, BIOS 1.21 04/26/2023
>> [ 6849.221833] Workqueue: events_unbound wq_barrier_func
>> [ 6849.221846] ==================================================================
> 
> That looks like the PENDING bit. The setting is atomic. Maybe there's a raw
> read? Can you map the addresses to lines?
> 
> Thanks.

Sadly not: I had to rebuild the kernel with debug on, so I am attempting to catch the issue again.

Are you interested in any of these:

# sudo dmesg --color=always | grep KCSAN | grep -v acpi | less -R
[  101.395134] BUG: KCSAN: data-race in xas_clear_mark / xas_find_marked
[  133.628459] BUG: KCSAN: data-race in vprintk_emit+0x343/0x400
[  154.742056] BUG: KCSAN: data-race in rcu_implicit_dynticks_qs / rcu_sched_clock_irq
[  171.626135] BUG: KCSAN: data-race in rcu_implicit_dynticks_qs / rcu_sched_clock_irq
[  209.239022] BUG: KCSAN: data-race in vprintk_emit+0x343/0x400
[  227.654170] BUG: KCSAN: data-race in rcu_implicit_dynticks_qs / rcu_sched_clock_irq
[  240.411681] BUG: KCSAN: data-race in _find_next_bit+0x42/0xf0
[  244.273756] BUG: KCSAN: data-race in mas_wr_bnode / mtree_range_walk
[  259.304431] BUG: KCSAN: data-race in mas_wr_bnode / mtree_range_walk
[  261.572037] BUG: KCSAN: data-race in poll_schedule_timeout.constprop.0 / pollwake
[  261.639803] BUG: KCSAN: data-race in mas_spanning_rebalance.isra.0 / mtree_range_walk
[  261.792478] BUG: KCSAN: data-race in mas_wr_bnode / mtree_range_walk
[  262.690859] BUG: KCSAN: data-race in mas_wr_bnode / mtree_range_walk
[  262.866290] BUG: KCSAN: data-race in __mod_lruvec_page_state / shmem_get_folio_gfp
[  262.873251] BUG: KCSAN: data-race in shmem_add_to_page_cache / shmem_recalc_inode
[  262.878189] BUG: KCSAN: data-race in _find_next_and_bit+0x43/0x120
[  268.948899] BUG: KCSAN: data-race in do_epoll_ctl / ep_poll_callback
[  268.990769] BUG: KCSAN: data-race in poll_schedule_timeout.constprop.0 / pollwake
[  269.231597] BUG: KCSAN: data-race in mas_wr_node_store / mtree_range_walk
[  271.133684] BUG: KCSAN: data-race in _find_next_bit+0x42/0xf0
[  271.329759] BUG: KCSAN: data-race in mas_wr_node_store / mtree_range_walk
[  273.815884] BUG: KCSAN: data-race in cgroup_freezer_migrate_task / handle_mm_fault
[  274.821427] BUG: KCSAN: data-race in _find_next_bit+0x42/0xf0
[  275.007630] BUG: KCSAN: data-race in poll_schedule_timeout.constprop.0 / pollwake
[  275.129286] BUG: KCSAN: data-race in _find_next_and_bit+0x43/0x120
[  275.602701] BUG: KCSAN: data-race in __mod_lruvec_page_state / folio_wait_bit_common
[  275.605323] BUG: KCSAN: data-race in __mod_lruvec_page_state / shmem_get_folio_gfp
[  275.634562] BUG: KCSAN: data-race in shmem_add_to_page_cache / shmem_recalc_inode
[  276.397103] BUG: KCSAN: data-race in do_epoll_ctl / ep_poll_callback
[  279.557086] BUG: KCSAN: data-race in _find_next_and_bit+0x43/0x120
[  282.374662] BUG: KCSAN: data-race in mas_descend_adopt / mtree_range_walk
[  282.640776] BUG: KCSAN: data-race in mas_spanning_rebalance.isra.0 / mtree_range_walk
[  285.180973] BUG: KCSAN: data-race in _find_next_bit+0x42/0xf0
[  289.606686] BUG: KCSAN: data-race in kernfs_refresh_inode / kernfs_refresh_inode
[  289.619587] BUG: KCSAN: data-race in kernfs_refresh_inode / kernfs_refresh_inode
[  289.625210] BUG: KCSAN: data-race in generic_fillattr / kernfs_refresh_inode
[  290.000921] BUG: KCSAN: data-race in kernfs_refresh_inode / kernfs_refresh_inode
[  297.491913] BUG: KCSAN: data-race in _find_next_bit+0x42/0xf0
[  303.411512] BUG: KCSAN: data-race in _find_next_bit+0x42/0xf0
[  317.191778] BUG: KCSAN: data-race in __read_end_io / folio_batch_move_lru
[  321.395561] BUG: KCSAN: data-race in n_tty_poll / n_tty_receive_buf_common
[  321.938843] BUG: KCSAN: data-race in n_tty_poll / n_tty_receive_buf_common
[  325.702280] BUG: KCSAN: data-race in tick_nohz_idle_stop_tick / tick_nohz_idle_stop_tick
[  326.930194] BUG: KCSAN: data-race in tick_sched_do_timer / tick_sched_do_timer
[  327.230053] BUG: KCSAN: data-race in tick_nohz_next_event+0xe7/0x1e0
[  329.501788] BUG: KCSAN: data-race in _find_next_and_bit+0x43/0x120
[  359.973752] BUG: KCSAN: data-race in tick_nohz_idle_stop_tick / tick_nohz_next_event
#

However, I naively set CONFIG_LOG_BUF_SHIFT to 22 and it rolled over, so the ring buffer
ran out of space ...

I will get them the next time ...

Best regards,
Mirsad Todorovac

Re: [BUG] KCSAN: data-race in process_one_work / process_one_work

[Mirsad Todorovac]

On 8/17/23 23:59, Tejun Heo wrote:
> On Thu, Aug 17, 2023 at 09:24:28PM +0200, Mirsad Todorovac wrote:
>> Hi,
>>
>> This is your friendly bug reporter.
>>
>> The environment is vanilla torvalds tree kernel on Ubuntu 22.04 LTS and on a Ryzen 7950X
>> assembled box.
>>
>> The kernel reports G taint "properietary module loaded", but I know of no module since
>> the boot state when the status was "Not tainted".
>>
>> Please find the complete dmesg output (or what's left in the ring buffer) and lshw output
>> attached.
>>
>> Here is the dmesg output excerpt:
>>
>> [ 6849.221584] ==================================================================
>> [ 6849.221607] BUG: KCSAN: data-race in process_one_work / process_one_work
>>
>> [ 6849.221635] write to 0xffff9b7440151398 of 8 bytes by task 6364 on cpu 7:
>> [ 6849.221647]  process_one_work+0x504/0x930
>> [ 6849.221660]  worker_thread+0x311/0x7e0
>> [ 6849.221673]  kthread+0x18b/0x1d0
>> [ 6849.221683]  ret_from_fork+0x43/0x70
>> [ 6849.221695]  ret_from_fork_asm+0x1b/0x30
>>
>> [ 6849.221712] read to 0xffff9b7440151398 of 8 bytes by task 5586 on cpu 28:
>> [ 6849.221724]  process_one_work+0x4e8/0x930
>> [ 6849.221737]  worker_thread+0x519/0x7e0
>> [ 6849.221749]  kthread+0x18b/0x1d0
>> [ 6849.221759]  ret_from_fork+0x43/0x70
>> [ 6849.221770]  ret_from_fork_asm+0x1b/0x30
>>
>> [ 6849.221786] value changed: 0x00000000000154d0 -> 0x00000000000154d1
>>
>> [ 6849.221802] Reported by Kernel Concurrency Sanitizer on:
>> [ 6849.221811] CPU: 28 PID: 5586 Comm: kworker/u64:0 Tainted: G             L     6.5.0-rc6-net-cfg-kcsan-00038-g16931859a650 #35
>> [ 6849.221825] Hardware name: ASRock X670E PG Lightning/X670E PG Lightning, BIOS 1.21 04/26/2023
>> [ 6849.221833] Workqueue: events_unbound wq_barrier_func
>> [ 6849.221846] ==================================================================
> 
> That looks like the PENDING bit. The setting is atomic. Maybe there's a raw
> read? Can you map the addresses to lines?
> 
> Thanks.

Good news:

[ 1863.554079] ==================================================================
[ 1863.554118] BUG: KCSAN: data-race in process_one_work / process_one_work

[ 1863.554142] write to 0xffff963d99d79998 of 8 bytes by task 5394 on cpu 27:
[ 1863.554154] process_one_work (kernel/workqueue.c:2598)
[ 1863.554166] worker_thread (./include/linux/list.h:292 kernel/workqueue.c:2752)
[ 1863.554177] kthread (kernel/kthread.c:389)
[ 1863.554186] ret_from_fork (arch/x86/kernel/process.c:145)
[ 1863.554197] ret_from_fork_asm (arch/x86/entry/entry_64.S:312)

[ 1863.554213] read to 0xffff963d99d79998 of 8 bytes by task 5450 on cpu 12:
[ 1863.554224] process_one_work (kernel/workqueue.c:2598)
[ 1863.554235] worker_thread (./include/linux/list.h:292 kernel/workqueue.c:2752)
[ 1863.554247] kthread (kernel/kthread.c:389)
[ 1863.554255] ret_from_fork (arch/x86/kernel/process.c:145)
[ 1863.554266] ret_from_fork_asm (arch/x86/entry/entry_64.S:312)

[ 1863.554280] value changed: 0x0000000000001766 -> 0x000000000000176a

[ 1863.554295] Reported by Kernel Concurrency Sanitizer on:
[ 1863.554303] CPU: 12 PID: 5450 Comm: kworker/u64:1 Tainted: G             L     6.5.0-rc6+ #44
[ 1863.554314] Hardware name: ASRock X670E PG Lightning/X670E PG Lightning, BIOS 1.21 04/26/2023
[ 1863.554322] Workqueue: btrfs-endio btrfs_end_bio_work [btrfs]
[ 1863.554941] ==================================================================


	lockdep_invariant_state(true);
:	pwq->stats[PWQ_STAT_STARTED]++;
	trace_workqueue_execute_start(work);
	worker->current_func(work);

Best regards,
Mirsad Todorovac

Re: [BUG] KCSAN: data-race in process_one_work / process_one_work

[Mirsad Todorovac]

On 8/18/23 10:10, Mirsad Todorovac wrote:
> 
> 
> On 8/17/23 23:59, Tejun Heo wrote:
>> On Thu, Aug 17, 2023 at 09:24:28PM +0200, Mirsad Todorovac wrote:
>>> Hi,
>>>
>>> This is your friendly bug reporter.
>>>
>>> The environment is vanilla torvalds tree kernel on Ubuntu 22.04 LTS and on a Ryzen 7950X
>>> assembled box.
>>>
>>> The kernel reports G taint "properietary module loaded", but I know of no module since
>>> the boot state when the status was "Not tainted".
>>>
>>> Please find the complete dmesg output (or what's left in the ring buffer) and lshw output
>>> attached.
>>>
>>> Here is the dmesg output excerpt:
>>>
>>> [ 6849.221584] ==================================================================
>>> [ 6849.221607] BUG: KCSAN: data-race in process_one_work / process_one_work
>>>
>>> [ 6849.221635] write to 0xffff9b7440151398 of 8 bytes by task 6364 on cpu 7:
>>> [ 6849.221647]  process_one_work+0x504/0x930
>>> [ 6849.221660]  worker_thread+0x311/0x7e0
>>> [ 6849.221673]  kthread+0x18b/0x1d0
>>> [ 6849.221683]  ret_from_fork+0x43/0x70
>>> [ 6849.221695]  ret_from_fork_asm+0x1b/0x30
>>>
>>> [ 6849.221712] read to 0xffff9b7440151398 of 8 bytes by task 5586 on cpu 28:
>>> [ 6849.221724]  process_one_work+0x4e8/0x930
>>> [ 6849.221737]  worker_thread+0x519/0x7e0
>>> [ 6849.221749]  kthread+0x18b/0x1d0
>>> [ 6849.221759]  ret_from_fork+0x43/0x70
>>> [ 6849.221770]  ret_from_fork_asm+0x1b/0x30
>>>
>>> [ 6849.221786] value changed: 0x00000000000154d0 -> 0x00000000000154d1
>>>
>>> [ 6849.221802] Reported by Kernel Concurrency Sanitizer on:
>>> [ 6849.221811] CPU: 28 PID: 5586 Comm: kworker/u64:0 Tainted: G             L     6.5.0-rc6-net-cfg-kcsan-00038-g16931859a650 #35
>>> [ 6849.221825] Hardware name: ASRock X670E PG Lightning/X670E PG Lightning, BIOS 1.21 04/26/2023
>>> [ 6849.221833] Workqueue: events_unbound wq_barrier_func
>>> [ 6849.221846] ==================================================================
>>
>> That looks like the PENDING bit. The setting is atomic. Maybe there's a raw
>> read? Can you map the addresses to lines?
>>
>> Thanks.
> 
> Good news:
> 
> [ 1863.554079] ==================================================================
> [ 1863.554118] BUG: KCSAN: data-race in process_one_work / process_one_work
> 
> [ 1863.554142] write to 0xffff963d99d79998 of 8 bytes by task 5394 on cpu 27:
> [ 1863.554154] process_one_work (kernel/workqueue.c:2598)
> [ 1863.554166] worker_thread (./include/linux/list.h:292 kernel/workqueue.c:2752)
> [ 1863.554177] kthread (kernel/kthread.c:389)
> [ 1863.554186] ret_from_fork (arch/x86/kernel/process.c:145)
> [ 1863.554197] ret_from_fork_asm (arch/x86/entry/entry_64.S:312)
> 
> [ 1863.554213] read to 0xffff963d99d79998 of 8 bytes by task 5450 on cpu 12:
> [ 1863.554224] process_one_work (kernel/workqueue.c:2598)
> [ 1863.554235] worker_thread (./include/linux/list.h:292 kernel/workqueue.c:2752)
> [ 1863.554247] kthread (kernel/kthread.c:389)
> [ 1863.554255] ret_from_fork (arch/x86/kernel/process.c:145)
> [ 1863.554266] ret_from_fork_asm (arch/x86/entry/entry_64.S:312)
> 
> [ 1863.554280] value changed: 0x0000000000001766 -> 0x000000000000176a
> 
> [ 1863.554295] Reported by Kernel Concurrency Sanitizer on:
> [ 1863.554303] CPU: 12 PID: 5450 Comm: kworker/u64:1 Tainted: G             L     6.5.0-rc6+ #44
> [ 1863.554314] Hardware name: ASRock X670E PG Lightning/X670E PG Lightning, BIOS 1.21 04/26/2023
> [ 1863.554322] Workqueue: btrfs-endio btrfs_end_bio_work [btrfs]
> [ 1863.554941] ==================================================================
> 
> 
>      lockdep_invariant_state(true);
> :    pwq->stats[PWQ_STAT_STARTED]++;
>      trace_workqueue_execute_start(work);
>      worker->current_func(work);

Just as an exercise, this seems to work, but it is probably not very clean and not very scalable:

diff --git a/kernel/workqueue.c b/kernel/workqueue.c
index 800b4208dba9..237e5800fbad 100644
--- a/kernel/workqueue.c
+++ b/kernel/workqueue.c
@@ -2595,7 +2595,7 @@ __acquires(&pool->lock)
          * workqueues), so hiding them isn't a problem.
          */
         lockdep_invariant_state(true);
-       pwq->stats[PWQ_STAT_STARTED]++;
+       atomic_inc((atomic_t *) &pwq->stats[PWQ_STAT_STARTED]);
         trace_workqueue_execute_start(work);
         worker->current_func(work);
         /*

--
Best regards,
Mirsad Todorovac

Re: [BUG] KCSAN: data-race in process_one_work / process_one_work

[Tejun Heo]

On Fri, Aug 18, 2023 at 01:58:27PM +0200, Mirsad Todorovac wrote:
> Just as an exercise, this seems to work, but it is probably not very clean and not very scalable:

pwq is already per-cpu. It's not strictly accessed per-cpu because workers
can go unbound but given that it's a stat counter, that doesn't really
matter all that much. Sounds like it should be marked so that kcsan ignores
it.

Thanks.

-- 
tejun

Re: [BUG] KCSAN: data-race in process_one_work / process_one_work

[Mirsad Todorovac]

On 8/22/23 21:52, Tejun Heo wrote:
> On Fri, Aug 18, 2023 at 01:58:27PM +0200, Mirsad Todorovac wrote:
>> Just as an exercise, this seems to work, but it is probably not very clean and not very scalable:
> 
> pwq is already per-cpu. It's not strictly accessed per-cpu because workers
> can go unbound but given that it's a stat counter, that doesn't really
> matter all that much. Sounds like it should be marked so that kcsan ignores
> it.
> 
> Thanks.

Hi, Mr. Heo,

Not at all.
  
Thanks for your review. The patch closed the KCSAN report, so I thought something was happening.

Kind regards,
Mirsad Todorovac