* [next] WARNING: suspicious RCU usage : include/linux/cgroup.h:494 suspicious rcu_dereference_check() usage
@ 2022-03-04 13:25 Naresh Kamboju
2022-03-04 19:38 ` Zhouyi Zhou
0 siblings, 1 reply; 8+ messages in thread
From: Naresh Kamboju @ 2022-03-04 13:25 UTC (permalink / raw)
To: Linux-Next Mailing List, open list, lkft-triage, rcu
Cc: Paul E. McKenney, Stephen Rothwell, Peter Zijlstra, Ingo Molnar,
Will Deacon
While booting x86_64 with linux next-20220304 kernel the following kernel
warning reported [1].
metadata:
git_ref: master
git_repo: https://gitlab.com/Linaro/lkft/mirrors/next/linux-next
git_sha: 6d284ba80c0c485bcaa7bdf67f232d572640edc4
git_describe: next-20220304
kernel-config: https://builds.tuxbuild.com/25uuYdm2vTO275aZ3IewZY5sKbU/config
warning log:
---------
[ 1.482171] MDS: Mitigation: Clear CPU buffers
[ 1.485680] Freeing SMP alternatives memory: 52K
[ 1.487341]
[ 1.488169] =============================
[ 1.488169] WARNING: suspicious RCU usage
[ 1.488169] 5.17.0-rc6-next-20220304 #1 Not tainted
[ 1.488169] -----------------------------
[ 1.488169] include/linux/cgroup.h:494 suspicious
rcu_dereference_check() usage!
[ 1.488169]
[ 1.488169] other info that might help us debug this:
[ 1.488169]
[ 1.488169]
[ 1.488169] rcu_scheduler_active = 1, debug_locks = 1
[ 1.488169] 2 locks held by kthreadd/2:
[ 1.488169] #0: ffff9ba440352330 (&p->pi_lock){....}-{2:2}, at:
task_rq_lock+0x2e/0x130
[ 1.488169] #1: ffff9ba7a7a2d058 (&rq->__lock){-...}-{2:2}, at:
task_rq_lock+0x5d/0x130
[ 1.488169]
[ 1.488169] stack backtrace:
[ 1.488169] CPU: 0 PID: 2 Comm: kthreadd Not tainted
5.17.0-rc6-next-20220304 #1
[ 1.488169] Hardware name: Supermicro SYS-5019S-ML/X11SSH-F, BIOS
2.5 11/26/2020
[ 1.488169] Call Trace:
[ 1.488169] <TASK>
[ 1.488169] dump_stack_lvl+0x49/0x5e
[ 1.488169] dump_stack+0x10/0x12
[ 1.488169] lockdep_rcu_suspicious+0xed/0xf8
[ 1.488169] cpuacct_charge+0x10c/0x120
[ 1.488169] update_curr+0x165/0x340
[ 1.488169] dequeue_entity+0x23/0x430
[ 1.488169] dequeue_task_fair+0xba/0x3b0
[ 1.488169] __do_set_cpus_allowed+0xca/0x2c0
[ 1.488169] __set_cpus_allowed_ptr_locked+0x128/0x1b0
[ 1.488169] set_cpus_allowed_ptr+0x43/0x70
[ 1.488169] kthreadd+0x49/0x230
[ 1.488169] ? kthread_is_per_cpu+0x30/0x30
[ 1.488169] ret_from_fork+0x22/0x30
[ 1.488169] </TASK>
[ 1.488169]
[ 1.488169] =============================
[ 1.488169] WARNING: suspicious RCU usage
[ 1.488169] 5.17.0-rc6-next-20220304 #1 Not tainted
[ 1.488169] -----------------------------
[ 1.488169] include/linux/cgroup.h:481 suspicious
rcu_dereference_check() usage!
[ 1.488169]
[ 1.488169] other info that might help us debug this:
[ 1.488169]
[ 1.488169]
[ 1.488169] rcu_scheduler_active = 1, debug_locks = 1
[ 1.488169] 2 locks held by kthreadd/2:
[ 1.488169] #0: ffff9ba440352330 (&p->pi_lock){....}-{2:2}, at:
task_rq_lock+0x2e/0x130
[ 1.488169] #1: ffff9ba7a7a2d058 (&rq->__lock){-...}-{2:2}, at:
task_rq_lock+0x5d/0x130
[ 1.488169]
[ 1.488169] stack backtrace:
[ 1.488169] CPU: 0 PID: 2 Comm: kthreadd Not tainted
5.17.0-rc6-next-20220304 #1
[ 1.488169] Hardware name: Supermicro SYS-5019S-ML/X11SSH-F, BIOS
2.5 11/26/2020
[ 1.488169] Call Trace:
[ 1.488169] <TASK>
[ 1.488169] dump_stack_lvl+0x49/0x5e
[ 1.488169] dump_stack+0x10/0x12
[ 1.488169] lockdep_rcu_suspicious+0xed/0xf8
[ 1.488169] update_curr+0x2b7/0x340
[ 1.488169] dequeue_entity+0x23/0x430
[ 1.488169] dequeue_task_fair+0xba/0x3b0
[ 1.488169] __do_set_cpus_allowed+0xca/0x2c0
[ 1.488169] __set_cpus_allowed_ptr_locked+0x128/0x1b0
[ 1.488169] set_cpus_allowed_ptr+0x43/0x70
[ 1.488169] kthreadd+0x49/0x230
[ 1.488169] ? kthread_is_per_cpu+0x30/0x30
[ 1.488169] ret_from_fork+0x22/0x30
[ 1.488169] </TASK>
[ 1.488169]
[ 1.488169] =============================
[ 1.488169] WARNING: suspicious RCU usage
[ 1.488169] 5.17.0-rc6-next-20220304 #1 Not tainted
[ 1.488169] -----------------------------
[ 1.488169] include/linux/cgroup.h:481 suspicious
rcu_dereference_check() usage!
[ 1.488169]
[ 1.488169] other info that might help us debug this:
[ 1.488169]
[ 1.488169]
[ 1.488169] rcu_scheduler_active = 1, debug_locks = 1
[ 1.488169] no locks held by kthreadd/2.
[ 1.488169]
[ 1.488169] stack backtrace:
[ 1.488169] CPU: 0 PID: 2 Comm: kthreadd Not tainted
5.17.0-rc6-next-20220304 #1
[ 1.488169] Hardware name: Supermicro SYS-5019S-ML/X11SSH-F, BIOS
2.5 11/26/2020
[ 1.488169] Call Trace:
[ 1.488169] <IRQ>
[ 1.488169] dump_stack_lvl+0x49/0x5e
[ 1.488169] dump_stack+0x10/0x12
[ 1.488169] lockdep_rcu_suspicious+0xed/0xf8
[ 1.488169] account_system_index_time+0x127/0x130
[ 1.488169] account_system_time+0x50/0x60
[ 1.488169] account_process_tick+0x59/0x80
[ 1.488169] update_process_times+0x58/0xe0
[ 1.488169] tick_periodic+0x37/0xf0
[ 1.488169] tick_handle_periodic+0x24/0x70
[ 1.488169] timer_interrupt+0x18/0x20
[ 1.488169] __handle_irq_event_percpu+0x95/0x2f0
[ 1.488169] handle_irq_event+0x39/0x80
[ 1.488169] handle_edge_irq+0xa4/0x240
[ 1.488169] __common_interrupt+0x8d/0x170
[ 1.488169] common_interrupt+0xbd/0xe0
[ 1.488169] </IRQ>
[ 1.488169] <TASK>
[ 1.488169] asm_common_interrupt+0x1e/0x40
[ 1.488169] RIP: 0010:_raw_spin_unlock_irqrestore+0x37/0x60
[ 1.488169] Code: fc 48 83 c7 18 53 48 89 f3 48 8b 75 08 e8 21 83
ed fe 4c 89 e7 e8 19 b0 ed fe 80 e7 02 74 06 e8 6f 77 fa fe fb bf 01
00 00 00 <e8> 24 6b e9 fe 65 8b 05 bd e1 28 66 85 c0 74 05 5b 41 5c 5d
c3 0f
[ 1.488169] RSP: 0000:ffffb75b0002fd50 EFLAGS: 00000202
[ 1.488169] RAX: 0000000000000007 RBX: 0000000000000246 RCX: 0000000000000000
[ 1.488169] RDX: 0000000000000000 RSI: ffffffff9a800a7c RDI: 0000000000000001
[ 1.488169] RBP: ffffb75b0002fd60 R08: 0000000000000001 R09: 0000000000000001
[ 1.488169] R10: 0000000000000002 R11: 0000000000000001 R12: ffff9ba440352318
[ 1.488169] R13: 0000000000000000 R14: 0000000000000000 R15: ffff9ba7a7a2d040
[ 1.488169] affine_move_task+0x2d4/0x5d0
[ 1.488169] ? __this_cpu_preempt_check+0x13/0x20
[ 1.488169] ? lock_is_held_type+0xdd/0x130
[ 1.488169] ? enqueue_entity+0x1b8/0x520
[ 1.488169] __set_cpus_allowed_ptr_locked+0x15c/0x1b0
[ 1.488169] set_cpus_allowed_ptr+0x43/0x70
[ 1.488169] kthreadd+0x49/0x230
[ 1.488169] ? kthread_is_per_cpu+0x30/0x30
[ 1.488169] ret_from_fork+0x22/0x30
[ 1.488169] </TASK>
[ 1.489211] smpboot: Estimated ratio of average max frequency by
base frequency (times 1024): 1126
[ 1.490189] smpboot: CPU0: Intel(R) Xeon(R) CPU E3-1220 v6 @
3.00GHz (family: 0x6, model: 0x9e, stepping: 0x9)
[ 1.491635] cblist_init_generic: Setting adjustable number of
callback queues.
[ 1.492171] cblist_init_generic: Setting shift to 2 and lim to 1.
[ 1.493226] cblist_init_generic: Setting shift to 2 and lim to 1.
[ 1.494226] cblist_init_generic: Setting shift to 2 and lim to 1.
[ 1.495219] Running RCU-tasks wait API self tests
[ 1.598317] Performance Events: PEBS fmt3+, Skylake events, 32-deep
LBR, full-width counters, Intel PMU driver.
[ 1.599176] ... version: 4
[ 1.600171] ... bit width: 48
[ 1.601171] ... generic registers: 8
[ 1.602171] ... value mask: 0000ffffffffffff
[ 1.603171] ... max period: 00007fffffffffff
[ 1.604176] ... fixed-purpose events: 3
[ 1.605171] ... event mask: 00000007000000ff
[ 1.606188] Callback from call_rcu_tasks_trace() invoked.
[ 1.607450] rcu: Hierarchical SRCU implementation.
[ 1.608310]
[ 1.609169] =============================
[ 1.609169] WARNING: suspicious RCU usage
[ 1.609169] 5.17.0-rc6-next-20220304 #1 Not tainted
[ 1.609169] -----------------------------
[ 1.609169] include/linux/cgroup.h:481 suspicious
rcu_dereference_check() usage!
[ 1.609169]
[ 1.609169] other info that might help us debug this:
[ 1.609169]
[ 1.609169]
[ 1.609169] rcu_scheduler_active = 1, debug_locks = 1
[ 1.609169] 1 lock held by migration/0/17:
[ 1.609169] #0: ffff9ba7a7a2d058 (&rq->__lock){-.-.}-{2:2}, at:
__schedule+0x12d/0xcb0
[ 1.609169]
[ 1.609169] stack backtrace:
[ 1.609169] CPU: 0 PID: 17 Comm: migration/0 Not tainted
5.17.0-rc6-next-20220304 #1
[ 1.609169] Hardware name: Supermicro SYS-5019S-ML/X11SSH-F, BIOS
2.5 11/26/2020
[ 1.609169] Stopper: 0x0 <- 0x0
[ 1.609169] Call Trace:
[ 1.609169] <TASK>
[ 1.609169] dump_stack_lvl+0x49/0x5e
[ 1.609169] dump_stack+0x10/0x12
[ 1.609169] lockdep_rcu_suspicious+0xed/0xf8
[ 1.609169] put_prev_task_stop+0x1dc/0x240
[ 1.609169] __schedule+0x751/0xcb0
[ 1.609169] ? trace_preempt_off+0x29/0xc0
[ 1.609169] ? smpboot_thread_fn+0x33/0x290
[ 1.609169] schedule+0x58/0xc0
[ 1.609169] smpboot_thread_fn+0xec/0x290
[ 1.609169] ? sort_range+0x30/0x30
[ 1.609169] kthread+0x107/0x130
[ 1.609169] ? kthread_complete_and_exit+0x20/0x20
[ 1.609169] ret_from_fork+0x22/0x30
[ 1.609169] </TASK>
[ 1.610276] smp: Bringing up secondary CPUs ...
[ 1.611596] x86: Booting SMP configuration:
[ 1.612179] .... node #0, CPUs: #1 #2 #3
[ 1.614396] smp: Brought up 1 node, 4 CPUs
Reported-by: Linux Kernel Functional Testing <lkft@linaro.org>
--
Linaro LKFT
https://lkft.linaro.org
[1] https://qa-reports.linaro.org/lkft/linux-next-master/build/next-20220304/testrun/8235955/suite/linux-log-parser/test/check-kernel-warning-4655400/log
^ permalink raw reply [flat|nested] 8+ messages in thread
* Re: [next] WARNING: suspicious RCU usage : include/linux/cgroup.h:494 suspicious rcu_dereference_check() usage
2022-03-04 13:25 [next] WARNING: suspicious RCU usage : include/linux/cgroup.h:494 suspicious rcu_dereference_check() usage Naresh Kamboju
@ 2022-03-04 19:38 ` Zhouyi Zhou
2022-03-04 19:44 ` Paul E. McKenney
0 siblings, 1 reply; 8+ messages in thread
From: Zhouyi Zhou @ 2022-03-04 19:38 UTC (permalink / raw)
To: Naresh Kamboju, zhouchengming
Cc: Linux-Next Mailing List, open list, lkft-triage, rcu,
Paul E. McKenney, Stephen Rothwell, Peter Zijlstra, Ingo Molnar,
Will Deacon
Hi,
I can reproduce these warnings on my X86 VM.
Following the my backtrace:
(gdb) bt
#0 lockdep_rcu_suspicious (file=file@entry=0xffffffff825ea8ff
"include/linux/cgroup.h", line=line@entry=494,
s=s@entry=0xffffffff825c5c50 "suspicious rcu_dereference_check()
usage") at ./arch/x86/include/asm/current.h:15
#1 0xffffffff81183103 in task_css (subsys_id=2,
task=0xffff888100804080) at ./include/linux/cgroup.h:494
#2 task_ca (tsk=0xffff888100804080) at kernel/sched/cpuacct.c:40
#3 cpuacct_charge (tsk=tsk@entry=0xffff888100804080,
cputime=cputime@entry=3344803) at kernel/sched/cpuacct.c:342
#4 0xffffffff81162655 in cgroup_account_cputime (delta_exec=3344803,
task=0xffff888100804080) at ./include/linux/cgroup.h:792
#5 update_curr (cfs_rq=cfs_rq@entry=0xffff88813b63f500) at
kernel/sched/fair.c:907
#6 0xffffffff81164797 in dequeue_entity (flags=10,
se=0xffff888100804100, cfs_rq=0xffff88813b63f500) at
kernel/sched/fair.c:5771
#7 dequeue_task_fair (rq=0xffff88813b63f440, p=0xffff888100804080,
flags=10) at kernel/sched/fair.c:5771
#8 0xffffffff8115412a in dequeue_task (flags=10,
p=0xffff888100804080, rq=0xffff88813b63f440) at
kernel/sched/core.c:2019
#9 __do_set_cpus_allowed (p=0xffff888100804080,
new_mask=0xffffffff831b4d40 <housekeeping+512>, flags=0) at
kernel/sched/core.c:2508
#10 0xffffffff811564ca in __set_cpus_allowed_ptr_locked
(p=p@entry=0xffff888100804080,
new_mask=new_mask@entry=0xffffffff831b4d40 <housekeeping+512>,
flags=flags@entry=0, rq=0xffff88813b63f440,
rf=rf@entry=0xffffc9000012bee8) at kernel/sched/core.c:2841
#11 0xffffffff81156573 in __set_cpus_allowed_ptr
(p=p@entry=0xffff888100804080, new_mask=0xffffffff831b4d40
<housekeeping+512>, flags=flags@entry=0)
at kernel/sched/core.c:2874
#12 0xffffffff8115664c in set_cpus_allowed_ptr
(p=p@entry=0xffff888100804080, new_mask=<optimized out>) at
kernel/sched/core.c:2879
#13 0xffffffff81144676 in kthreadd (unused=<optimized out>) at
kernel/kthread.c:724
#14 0xffffffff810019df in ret_from_fork () at arch/x86/entry/entry_64.S:295
#15 0x0000000000000000 in ?? ()
Do the warnings have something to do with commit
dc6e0818bc9a0336d9accf3ea35d146d72aa7a18 (sched/cpuacct: Optimize away
RCU read lock) ?
Many thanks
Zhouyi
On Fri, Mar 4, 2022 at 10:43 PM Naresh Kamboju
<naresh.kamboju@linaro.org> wrote:
>
> While booting x86_64 with linux next-20220304 kernel the following kernel
> warning reported [1].
>
> metadata:
> git_ref: master
> git_repo: https://gitlab.com/Linaro/lkft/mirrors/next/linux-next
> git_sha: 6d284ba80c0c485bcaa7bdf67f232d572640edc4
> git_describe: next-20220304
> kernel-config: https://builds.tuxbuild.com/25uuYdm2vTO275aZ3IewZY5sKbU/config
>
>
> warning log:
> ---------
> [ 1.482171] MDS: Mitigation: Clear CPU buffers
> [ 1.485680] Freeing SMP alternatives memory: 52K
> [ 1.487341]
> [ 1.488169] =============================
> [ 1.488169] WARNING: suspicious RCU usage
> [ 1.488169] 5.17.0-rc6-next-20220304 #1 Not tainted
> [ 1.488169] -----------------------------
> [ 1.488169] include/linux/cgroup.h:494 suspicious
> rcu_dereference_check() usage!
> [ 1.488169]
> [ 1.488169] other info that might help us debug this:
> [ 1.488169]
> [ 1.488169]
> [ 1.488169] rcu_scheduler_active = 1, debug_locks = 1
> [ 1.488169] 2 locks held by kthreadd/2:
> [ 1.488169] #0: ffff9ba440352330 (&p->pi_lock){....}-{2:2}, at:
> task_rq_lock+0x2e/0x130
> [ 1.488169] #1: ffff9ba7a7a2d058 (&rq->__lock){-...}-{2:2}, at:
> task_rq_lock+0x5d/0x130
> [ 1.488169]
> [ 1.488169] stack backtrace:
> [ 1.488169] CPU: 0 PID: 2 Comm: kthreadd Not tainted
> 5.17.0-rc6-next-20220304 #1
> [ 1.488169] Hardware name: Supermicro SYS-5019S-ML/X11SSH-F, BIOS
> 2.5 11/26/2020
> [ 1.488169] Call Trace:
> [ 1.488169] <TASK>
> [ 1.488169] dump_stack_lvl+0x49/0x5e
> [ 1.488169] dump_stack+0x10/0x12
> [ 1.488169] lockdep_rcu_suspicious+0xed/0xf8
> [ 1.488169] cpuacct_charge+0x10c/0x120
> [ 1.488169] update_curr+0x165/0x340
> [ 1.488169] dequeue_entity+0x23/0x430
> [ 1.488169] dequeue_task_fair+0xba/0x3b0
> [ 1.488169] __do_set_cpus_allowed+0xca/0x2c0
> [ 1.488169] __set_cpus_allowed_ptr_locked+0x128/0x1b0
> [ 1.488169] set_cpus_allowed_ptr+0x43/0x70
> [ 1.488169] kthreadd+0x49/0x230
> [ 1.488169] ? kthread_is_per_cpu+0x30/0x30
> [ 1.488169] ret_from_fork+0x22/0x30
> [ 1.488169] </TASK>
> [ 1.488169]
> [ 1.488169] =============================
> [ 1.488169] WARNING: suspicious RCU usage
> [ 1.488169] 5.17.0-rc6-next-20220304 #1 Not tainted
> [ 1.488169] -----------------------------
> [ 1.488169] include/linux/cgroup.h:481 suspicious
> rcu_dereference_check() usage!
> [ 1.488169]
> [ 1.488169] other info that might help us debug this:
> [ 1.488169]
> [ 1.488169]
> [ 1.488169] rcu_scheduler_active = 1, debug_locks = 1
> [ 1.488169] 2 locks held by kthreadd/2:
> [ 1.488169] #0: ffff9ba440352330 (&p->pi_lock){....}-{2:2}, at:
> task_rq_lock+0x2e/0x130
> [ 1.488169] #1: ffff9ba7a7a2d058 (&rq->__lock){-...}-{2:2}, at:
> task_rq_lock+0x5d/0x130
> [ 1.488169]
> [ 1.488169] stack backtrace:
> [ 1.488169] CPU: 0 PID: 2 Comm: kthreadd Not tainted
> 5.17.0-rc6-next-20220304 #1
> [ 1.488169] Hardware name: Supermicro SYS-5019S-ML/X11SSH-F, BIOS
> 2.5 11/26/2020
> [ 1.488169] Call Trace:
> [ 1.488169] <TASK>
> [ 1.488169] dump_stack_lvl+0x49/0x5e
> [ 1.488169] dump_stack+0x10/0x12
> [ 1.488169] lockdep_rcu_suspicious+0xed/0xf8
> [ 1.488169] update_curr+0x2b7/0x340
> [ 1.488169] dequeue_entity+0x23/0x430
> [ 1.488169] dequeue_task_fair+0xba/0x3b0
> [ 1.488169] __do_set_cpus_allowed+0xca/0x2c0
> [ 1.488169] __set_cpus_allowed_ptr_locked+0x128/0x1b0
> [ 1.488169] set_cpus_allowed_ptr+0x43/0x70
> [ 1.488169] kthreadd+0x49/0x230
> [ 1.488169] ? kthread_is_per_cpu+0x30/0x30
> [ 1.488169] ret_from_fork+0x22/0x30
> [ 1.488169] </TASK>
> [ 1.488169]
> [ 1.488169] =============================
> [ 1.488169] WARNING: suspicious RCU usage
> [ 1.488169] 5.17.0-rc6-next-20220304 #1 Not tainted
> [ 1.488169] -----------------------------
> [ 1.488169] include/linux/cgroup.h:481 suspicious
> rcu_dereference_check() usage!
> [ 1.488169]
> [ 1.488169] other info that might help us debug this:
> [ 1.488169]
> [ 1.488169]
> [ 1.488169] rcu_scheduler_active = 1, debug_locks = 1
> [ 1.488169] no locks held by kthreadd/2.
> [ 1.488169]
> [ 1.488169] stack backtrace:
> [ 1.488169] CPU: 0 PID: 2 Comm: kthreadd Not tainted
> 5.17.0-rc6-next-20220304 #1
> [ 1.488169] Hardware name: Supermicro SYS-5019S-ML/X11SSH-F, BIOS
> 2.5 11/26/2020
> [ 1.488169] Call Trace:
> [ 1.488169] <IRQ>
> [ 1.488169] dump_stack_lvl+0x49/0x5e
> [ 1.488169] dump_stack+0x10/0x12
> [ 1.488169] lockdep_rcu_suspicious+0xed/0xf8
> [ 1.488169] account_system_index_time+0x127/0x130
> [ 1.488169] account_system_time+0x50/0x60
> [ 1.488169] account_process_tick+0x59/0x80
> [ 1.488169] update_process_times+0x58/0xe0
> [ 1.488169] tick_periodic+0x37/0xf0
> [ 1.488169] tick_handle_periodic+0x24/0x70
> [ 1.488169] timer_interrupt+0x18/0x20
> [ 1.488169] __handle_irq_event_percpu+0x95/0x2f0
> [ 1.488169] handle_irq_event+0x39/0x80
> [ 1.488169] handle_edge_irq+0xa4/0x240
> [ 1.488169] __common_interrupt+0x8d/0x170
> [ 1.488169] common_interrupt+0xbd/0xe0
> [ 1.488169] </IRQ>
> [ 1.488169] <TASK>
> [ 1.488169] asm_common_interrupt+0x1e/0x40
> [ 1.488169] RIP: 0010:_raw_spin_unlock_irqrestore+0x37/0x60
> [ 1.488169] Code: fc 48 83 c7 18 53 48 89 f3 48 8b 75 08 e8 21 83
> ed fe 4c 89 e7 e8 19 b0 ed fe 80 e7 02 74 06 e8 6f 77 fa fe fb bf 01
> 00 00 00 <e8> 24 6b e9 fe 65 8b 05 bd e1 28 66 85 c0 74 05 5b 41 5c 5d
> c3 0f
> [ 1.488169] RSP: 0000:ffffb75b0002fd50 EFLAGS: 00000202
> [ 1.488169] RAX: 0000000000000007 RBX: 0000000000000246 RCX: 0000000000000000
> [ 1.488169] RDX: 0000000000000000 RSI: ffffffff9a800a7c RDI: 0000000000000001
> [ 1.488169] RBP: ffffb75b0002fd60 R08: 0000000000000001 R09: 0000000000000001
> [ 1.488169] R10: 0000000000000002 R11: 0000000000000001 R12: ffff9ba440352318
> [ 1.488169] R13: 0000000000000000 R14: 0000000000000000 R15: ffff9ba7a7a2d040
> [ 1.488169] affine_move_task+0x2d4/0x5d0
> [ 1.488169] ? __this_cpu_preempt_check+0x13/0x20
> [ 1.488169] ? lock_is_held_type+0xdd/0x130
> [ 1.488169] ? enqueue_entity+0x1b8/0x520
> [ 1.488169] __set_cpus_allowed_ptr_locked+0x15c/0x1b0
> [ 1.488169] set_cpus_allowed_ptr+0x43/0x70
> [ 1.488169] kthreadd+0x49/0x230
> [ 1.488169] ? kthread_is_per_cpu+0x30/0x30
> [ 1.488169] ret_from_fork+0x22/0x30
> [ 1.488169] </TASK>
> [ 1.489211] smpboot: Estimated ratio of average max frequency by
> base frequency (times 1024): 1126
> [ 1.490189] smpboot: CPU0: Intel(R) Xeon(R) CPU E3-1220 v6 @
> 3.00GHz (family: 0x6, model: 0x9e, stepping: 0x9)
> [ 1.491635] cblist_init_generic: Setting adjustable number of
> callback queues.
> [ 1.492171] cblist_init_generic: Setting shift to 2 and lim to 1.
> [ 1.493226] cblist_init_generic: Setting shift to 2 and lim to 1.
> [ 1.494226] cblist_init_generic: Setting shift to 2 and lim to 1.
> [ 1.495219] Running RCU-tasks wait API self tests
> [ 1.598317] Performance Events: PEBS fmt3+, Skylake events, 32-deep
> LBR, full-width counters, Intel PMU driver.
> [ 1.599176] ... version: 4
> [ 1.600171] ... bit width: 48
> [ 1.601171] ... generic registers: 8
> [ 1.602171] ... value mask: 0000ffffffffffff
> [ 1.603171] ... max period: 00007fffffffffff
> [ 1.604176] ... fixed-purpose events: 3
> [ 1.605171] ... event mask: 00000007000000ff
> [ 1.606188] Callback from call_rcu_tasks_trace() invoked.
> [ 1.607450] rcu: Hierarchical SRCU implementation.
> [ 1.608310]
> [ 1.609169] =============================
> [ 1.609169] WARNING: suspicious RCU usage
> [ 1.609169] 5.17.0-rc6-next-20220304 #1 Not tainted
> [ 1.609169] -----------------------------
> [ 1.609169] include/linux/cgroup.h:481 suspicious
> rcu_dereference_check() usage!
> [ 1.609169]
> [ 1.609169] other info that might help us debug this:
> [ 1.609169]
> [ 1.609169]
> [ 1.609169] rcu_scheduler_active = 1, debug_locks = 1
> [ 1.609169] 1 lock held by migration/0/17:
> [ 1.609169] #0: ffff9ba7a7a2d058 (&rq->__lock){-.-.}-{2:2}, at:
> __schedule+0x12d/0xcb0
> [ 1.609169]
> [ 1.609169] stack backtrace:
> [ 1.609169] CPU: 0 PID: 17 Comm: migration/0 Not tainted
> 5.17.0-rc6-next-20220304 #1
> [ 1.609169] Hardware name: Supermicro SYS-5019S-ML/X11SSH-F, BIOS
> 2.5 11/26/2020
> [ 1.609169] Stopper: 0x0 <- 0x0
> [ 1.609169] Call Trace:
> [ 1.609169] <TASK>
> [ 1.609169] dump_stack_lvl+0x49/0x5e
> [ 1.609169] dump_stack+0x10/0x12
> [ 1.609169] lockdep_rcu_suspicious+0xed/0xf8
> [ 1.609169] put_prev_task_stop+0x1dc/0x240
> [ 1.609169] __schedule+0x751/0xcb0
> [ 1.609169] ? trace_preempt_off+0x29/0xc0
> [ 1.609169] ? smpboot_thread_fn+0x33/0x290
> [ 1.609169] schedule+0x58/0xc0
> [ 1.609169] smpboot_thread_fn+0xec/0x290
> [ 1.609169] ? sort_range+0x30/0x30
> [ 1.609169] kthread+0x107/0x130
> [ 1.609169] ? kthread_complete_and_exit+0x20/0x20
> [ 1.609169] ret_from_fork+0x22/0x30
> [ 1.609169] </TASK>
> [ 1.610276] smp: Bringing up secondary CPUs ...
> [ 1.611596] x86: Booting SMP configuration:
> [ 1.612179] .... node #0, CPUs: #1 #2 #3
> [ 1.614396] smp: Brought up 1 node, 4 CPUs
>
> Reported-by: Linux Kernel Functional Testing <lkft@linaro.org>
>
> --
> Linaro LKFT
> https://lkft.linaro.org
>
> [1] https://qa-reports.linaro.org/lkft/linux-next-master/build/next-20220304/testrun/8235955/suite/linux-log-parser/test/check-kernel-warning-4655400/log
^ permalink raw reply [flat|nested] 8+ messages in thread
* Re: [next] WARNING: suspicious RCU usage : include/linux/cgroup.h:494 suspicious rcu_dereference_check() usage
2022-03-04 19:38 ` Zhouyi Zhou
@ 2022-03-04 19:44 ` Paul E. McKenney
2022-03-04 20:28 ` Zhouyi Zhou
0 siblings, 1 reply; 8+ messages in thread
From: Paul E. McKenney @ 2022-03-04 19:44 UTC (permalink / raw)
To: Zhouyi Zhou
Cc: Naresh Kamboju, zhouchengming, Linux-Next Mailing List,
open list, lkft-triage, rcu, Stephen Rothwell, Peter Zijlstra,
Ingo Molnar, Will Deacon
On Sat, Mar 05, 2022 at 03:38:33AM +0800, Zhouyi Zhou wrote:
> Hi,
> I can reproduce these warnings on my X86 VM.
> Following the my backtrace:
>
> (gdb) bt
> #0 lockdep_rcu_suspicious (file=file@entry=0xffffffff825ea8ff
> "include/linux/cgroup.h", line=line@entry=494,
> s=s@entry=0xffffffff825c5c50 "suspicious rcu_dereference_check()
> usage") at ./arch/x86/include/asm/current.h:15
> #1 0xffffffff81183103 in task_css (subsys_id=2,
> task=0xffff888100804080) at ./include/linux/cgroup.h:494
> #2 task_ca (tsk=0xffff888100804080) at kernel/sched/cpuacct.c:40
> #3 cpuacct_charge (tsk=tsk@entry=0xffff888100804080,
> cputime=cputime@entry=3344803) at kernel/sched/cpuacct.c:342
> #4 0xffffffff81162655 in cgroup_account_cputime (delta_exec=3344803,
> task=0xffff888100804080) at ./include/linux/cgroup.h:792
> #5 update_curr (cfs_rq=cfs_rq@entry=0xffff88813b63f500) at
> kernel/sched/fair.c:907
> #6 0xffffffff81164797 in dequeue_entity (flags=10,
> se=0xffff888100804100, cfs_rq=0xffff88813b63f500) at
> kernel/sched/fair.c:5771
> #7 dequeue_task_fair (rq=0xffff88813b63f440, p=0xffff888100804080,
> flags=10) at kernel/sched/fair.c:5771
> #8 0xffffffff8115412a in dequeue_task (flags=10,
> p=0xffff888100804080, rq=0xffff88813b63f440) at
> kernel/sched/core.c:2019
> #9 __do_set_cpus_allowed (p=0xffff888100804080,
> new_mask=0xffffffff831b4d40 <housekeeping+512>, flags=0) at
> kernel/sched/core.c:2508
> #10 0xffffffff811564ca in __set_cpus_allowed_ptr_locked
> (p=p@entry=0xffff888100804080,
> new_mask=new_mask@entry=0xffffffff831b4d40 <housekeeping+512>,
> flags=flags@entry=0, rq=0xffff88813b63f440,
> rf=rf@entry=0xffffc9000012bee8) at kernel/sched/core.c:2841
> #11 0xffffffff81156573 in __set_cpus_allowed_ptr
> (p=p@entry=0xffff888100804080, new_mask=0xffffffff831b4d40
> <housekeeping+512>, flags=flags@entry=0)
> at kernel/sched/core.c:2874
> #12 0xffffffff8115664c in set_cpus_allowed_ptr
> (p=p@entry=0xffff888100804080, new_mask=<optimized out>) at
> kernel/sched/core.c:2879
> #13 0xffffffff81144676 in kthreadd (unused=<optimized out>) at
> kernel/kthread.c:724
> #14 0xffffffff810019df in ret_from_fork () at arch/x86/entry/entry_64.S:295
> #15 0x0000000000000000 in ?? ()
>
> Do the warnings have something to do with commit
> dc6e0818bc9a0336d9accf3ea35d146d72aa7a18 (sched/cpuacct: Optimize away
> RCU read lock) ?
If you have not already done so, could you please try running on this
commit and then on the commit immediately preceding it? Just as a
authoritative way to answer your question. ;-)
Thanx, Paul
> Many thanks
> Zhouyi
>
> On Fri, Mar 4, 2022 at 10:43 PM Naresh Kamboju
> <naresh.kamboju@linaro.org> wrote:
> >
> > While booting x86_64 with linux next-20220304 kernel the following kernel
> > warning reported [1].
> >
> > metadata:
> > git_ref: master
> > git_repo: https://gitlab.com/Linaro/lkft/mirrors/next/linux-next
> > git_sha: 6d284ba80c0c485bcaa7bdf67f232d572640edc4
> > git_describe: next-20220304
> > kernel-config: https://builds.tuxbuild.com/25uuYdm2vTO275aZ3IewZY5sKbU/config
> >
> >
> > warning log:
> > ---------
> > [ 1.482171] MDS: Mitigation: Clear CPU buffers
> > [ 1.485680] Freeing SMP alternatives memory: 52K
> > [ 1.487341]
> > [ 1.488169] =============================
> > [ 1.488169] WARNING: suspicious RCU usage
> > [ 1.488169] 5.17.0-rc6-next-20220304 #1 Not tainted
> > [ 1.488169] -----------------------------
> > [ 1.488169] include/linux/cgroup.h:494 suspicious
> > rcu_dereference_check() usage!
> > [ 1.488169]
> > [ 1.488169] other info that might help us debug this:
> > [ 1.488169]
> > [ 1.488169]
> > [ 1.488169] rcu_scheduler_active = 1, debug_locks = 1
> > [ 1.488169] 2 locks held by kthreadd/2:
> > [ 1.488169] #0: ffff9ba440352330 (&p->pi_lock){....}-{2:2}, at:
> > task_rq_lock+0x2e/0x130
> > [ 1.488169] #1: ffff9ba7a7a2d058 (&rq->__lock){-...}-{2:2}, at:
> > task_rq_lock+0x5d/0x130
> > [ 1.488169]
> > [ 1.488169] stack backtrace:
> > [ 1.488169] CPU: 0 PID: 2 Comm: kthreadd Not tainted
> > 5.17.0-rc6-next-20220304 #1
> > [ 1.488169] Hardware name: Supermicro SYS-5019S-ML/X11SSH-F, BIOS
> > 2.5 11/26/2020
> > [ 1.488169] Call Trace:
> > [ 1.488169] <TASK>
> > [ 1.488169] dump_stack_lvl+0x49/0x5e
> > [ 1.488169] dump_stack+0x10/0x12
> > [ 1.488169] lockdep_rcu_suspicious+0xed/0xf8
> > [ 1.488169] cpuacct_charge+0x10c/0x120
> > [ 1.488169] update_curr+0x165/0x340
> > [ 1.488169] dequeue_entity+0x23/0x430
> > [ 1.488169] dequeue_task_fair+0xba/0x3b0
> > [ 1.488169] __do_set_cpus_allowed+0xca/0x2c0
> > [ 1.488169] __set_cpus_allowed_ptr_locked+0x128/0x1b0
> > [ 1.488169] set_cpus_allowed_ptr+0x43/0x70
> > [ 1.488169] kthreadd+0x49/0x230
> > [ 1.488169] ? kthread_is_per_cpu+0x30/0x30
> > [ 1.488169] ret_from_fork+0x22/0x30
> > [ 1.488169] </TASK>
> > [ 1.488169]
> > [ 1.488169] =============================
> > [ 1.488169] WARNING: suspicious RCU usage
> > [ 1.488169] 5.17.0-rc6-next-20220304 #1 Not tainted
> > [ 1.488169] -----------------------------
> > [ 1.488169] include/linux/cgroup.h:481 suspicious
> > rcu_dereference_check() usage!
> > [ 1.488169]
> > [ 1.488169] other info that might help us debug this:
> > [ 1.488169]
> > [ 1.488169]
> > [ 1.488169] rcu_scheduler_active = 1, debug_locks = 1
> > [ 1.488169] 2 locks held by kthreadd/2:
> > [ 1.488169] #0: ffff9ba440352330 (&p->pi_lock){....}-{2:2}, at:
> > task_rq_lock+0x2e/0x130
> > [ 1.488169] #1: ffff9ba7a7a2d058 (&rq->__lock){-...}-{2:2}, at:
> > task_rq_lock+0x5d/0x130
> > [ 1.488169]
> > [ 1.488169] stack backtrace:
> > [ 1.488169] CPU: 0 PID: 2 Comm: kthreadd Not tainted
> > 5.17.0-rc6-next-20220304 #1
> > [ 1.488169] Hardware name: Supermicro SYS-5019S-ML/X11SSH-F, BIOS
> > 2.5 11/26/2020
> > [ 1.488169] Call Trace:
> > [ 1.488169] <TASK>
> > [ 1.488169] dump_stack_lvl+0x49/0x5e
> > [ 1.488169] dump_stack+0x10/0x12
> > [ 1.488169] lockdep_rcu_suspicious+0xed/0xf8
> > [ 1.488169] update_curr+0x2b7/0x340
> > [ 1.488169] dequeue_entity+0x23/0x430
> > [ 1.488169] dequeue_task_fair+0xba/0x3b0
> > [ 1.488169] __do_set_cpus_allowed+0xca/0x2c0
> > [ 1.488169] __set_cpus_allowed_ptr_locked+0x128/0x1b0
> > [ 1.488169] set_cpus_allowed_ptr+0x43/0x70
> > [ 1.488169] kthreadd+0x49/0x230
> > [ 1.488169] ? kthread_is_per_cpu+0x30/0x30
> > [ 1.488169] ret_from_fork+0x22/0x30
> > [ 1.488169] </TASK>
> > [ 1.488169]
> > [ 1.488169] =============================
> > [ 1.488169] WARNING: suspicious RCU usage
> > [ 1.488169] 5.17.0-rc6-next-20220304 #1 Not tainted
> > [ 1.488169] -----------------------------
> > [ 1.488169] include/linux/cgroup.h:481 suspicious
> > rcu_dereference_check() usage!
> > [ 1.488169]
> > [ 1.488169] other info that might help us debug this:
> > [ 1.488169]
> > [ 1.488169]
> > [ 1.488169] rcu_scheduler_active = 1, debug_locks = 1
> > [ 1.488169] no locks held by kthreadd/2.
> > [ 1.488169]
> > [ 1.488169] stack backtrace:
> > [ 1.488169] CPU: 0 PID: 2 Comm: kthreadd Not tainted
> > 5.17.0-rc6-next-20220304 #1
> > [ 1.488169] Hardware name: Supermicro SYS-5019S-ML/X11SSH-F, BIOS
> > 2.5 11/26/2020
> > [ 1.488169] Call Trace:
> > [ 1.488169] <IRQ>
> > [ 1.488169] dump_stack_lvl+0x49/0x5e
> > [ 1.488169] dump_stack+0x10/0x12
> > [ 1.488169] lockdep_rcu_suspicious+0xed/0xf8
> > [ 1.488169] account_system_index_time+0x127/0x130
> > [ 1.488169] account_system_time+0x50/0x60
> > [ 1.488169] account_process_tick+0x59/0x80
> > [ 1.488169] update_process_times+0x58/0xe0
> > [ 1.488169] tick_periodic+0x37/0xf0
> > [ 1.488169] tick_handle_periodic+0x24/0x70
> > [ 1.488169] timer_interrupt+0x18/0x20
> > [ 1.488169] __handle_irq_event_percpu+0x95/0x2f0
> > [ 1.488169] handle_irq_event+0x39/0x80
> > [ 1.488169] handle_edge_irq+0xa4/0x240
> > [ 1.488169] __common_interrupt+0x8d/0x170
> > [ 1.488169] common_interrupt+0xbd/0xe0
> > [ 1.488169] </IRQ>
> > [ 1.488169] <TASK>
> > [ 1.488169] asm_common_interrupt+0x1e/0x40
> > [ 1.488169] RIP: 0010:_raw_spin_unlock_irqrestore+0x37/0x60
> > [ 1.488169] Code: fc 48 83 c7 18 53 48 89 f3 48 8b 75 08 e8 21 83
> > ed fe 4c 89 e7 e8 19 b0 ed fe 80 e7 02 74 06 e8 6f 77 fa fe fb bf 01
> > 00 00 00 <e8> 24 6b e9 fe 65 8b 05 bd e1 28 66 85 c0 74 05 5b 41 5c 5d
> > c3 0f
> > [ 1.488169] RSP: 0000:ffffb75b0002fd50 EFLAGS: 00000202
> > [ 1.488169] RAX: 0000000000000007 RBX: 0000000000000246 RCX: 0000000000000000
> > [ 1.488169] RDX: 0000000000000000 RSI: ffffffff9a800a7c RDI: 0000000000000001
> > [ 1.488169] RBP: ffffb75b0002fd60 R08: 0000000000000001 R09: 0000000000000001
> > [ 1.488169] R10: 0000000000000002 R11: 0000000000000001 R12: ffff9ba440352318
> > [ 1.488169] R13: 0000000000000000 R14: 0000000000000000 R15: ffff9ba7a7a2d040
> > [ 1.488169] affine_move_task+0x2d4/0x5d0
> > [ 1.488169] ? __this_cpu_preempt_check+0x13/0x20
> > [ 1.488169] ? lock_is_held_type+0xdd/0x130
> > [ 1.488169] ? enqueue_entity+0x1b8/0x520
> > [ 1.488169] __set_cpus_allowed_ptr_locked+0x15c/0x1b0
> > [ 1.488169] set_cpus_allowed_ptr+0x43/0x70
> > [ 1.488169] kthreadd+0x49/0x230
> > [ 1.488169] ? kthread_is_per_cpu+0x30/0x30
> > [ 1.488169] ret_from_fork+0x22/0x30
> > [ 1.488169] </TASK>
> > [ 1.489211] smpboot: Estimated ratio of average max frequency by
> > base frequency (times 1024): 1126
> > [ 1.490189] smpboot: CPU0: Intel(R) Xeon(R) CPU E3-1220 v6 @
> > 3.00GHz (family: 0x6, model: 0x9e, stepping: 0x9)
> > [ 1.491635] cblist_init_generic: Setting adjustable number of
> > callback queues.
> > [ 1.492171] cblist_init_generic: Setting shift to 2 and lim to 1.
> > [ 1.493226] cblist_init_generic: Setting shift to 2 and lim to 1.
> > [ 1.494226] cblist_init_generic: Setting shift to 2 and lim to 1.
> > [ 1.495219] Running RCU-tasks wait API self tests
> > [ 1.598317] Performance Events: PEBS fmt3+, Skylake events, 32-deep
> > LBR, full-width counters, Intel PMU driver.
> > [ 1.599176] ... version: 4
> > [ 1.600171] ... bit width: 48
> > [ 1.601171] ... generic registers: 8
> > [ 1.602171] ... value mask: 0000ffffffffffff
> > [ 1.603171] ... max period: 00007fffffffffff
> > [ 1.604176] ... fixed-purpose events: 3
> > [ 1.605171] ... event mask: 00000007000000ff
> > [ 1.606188] Callback from call_rcu_tasks_trace() invoked.
> > [ 1.607450] rcu: Hierarchical SRCU implementation.
> > [ 1.608310]
> > [ 1.609169] =============================
> > [ 1.609169] WARNING: suspicious RCU usage
> > [ 1.609169] 5.17.0-rc6-next-20220304 #1 Not tainted
> > [ 1.609169] -----------------------------
> > [ 1.609169] include/linux/cgroup.h:481 suspicious
> > rcu_dereference_check() usage!
> > [ 1.609169]
> > [ 1.609169] other info that might help us debug this:
> > [ 1.609169]
> > [ 1.609169]
> > [ 1.609169] rcu_scheduler_active = 1, debug_locks = 1
> > [ 1.609169] 1 lock held by migration/0/17:
> > [ 1.609169] #0: ffff9ba7a7a2d058 (&rq->__lock){-.-.}-{2:2}, at:
> > __schedule+0x12d/0xcb0
> > [ 1.609169]
> > [ 1.609169] stack backtrace:
> > [ 1.609169] CPU: 0 PID: 17 Comm: migration/0 Not tainted
> > 5.17.0-rc6-next-20220304 #1
> > [ 1.609169] Hardware name: Supermicro SYS-5019S-ML/X11SSH-F, BIOS
> > 2.5 11/26/2020
> > [ 1.609169] Stopper: 0x0 <- 0x0
> > [ 1.609169] Call Trace:
> > [ 1.609169] <TASK>
> > [ 1.609169] dump_stack_lvl+0x49/0x5e
> > [ 1.609169] dump_stack+0x10/0x12
> > [ 1.609169] lockdep_rcu_suspicious+0xed/0xf8
> > [ 1.609169] put_prev_task_stop+0x1dc/0x240
> > [ 1.609169] __schedule+0x751/0xcb0
> > [ 1.609169] ? trace_preempt_off+0x29/0xc0
> > [ 1.609169] ? smpboot_thread_fn+0x33/0x290
> > [ 1.609169] schedule+0x58/0xc0
> > [ 1.609169] smpboot_thread_fn+0xec/0x290
> > [ 1.609169] ? sort_range+0x30/0x30
> > [ 1.609169] kthread+0x107/0x130
> > [ 1.609169] ? kthread_complete_and_exit+0x20/0x20
> > [ 1.609169] ret_from_fork+0x22/0x30
> > [ 1.609169] </TASK>
> > [ 1.610276] smp: Bringing up secondary CPUs ...
> > [ 1.611596] x86: Booting SMP configuration:
> > [ 1.612179] .... node #0, CPUs: #1 #2 #3
> > [ 1.614396] smp: Brought up 1 node, 4 CPUs
> >
> > Reported-by: Linux Kernel Functional Testing <lkft@linaro.org>
> >
> > --
> > Linaro LKFT
> > https://lkft.linaro.org
> >
> > [1] https://qa-reports.linaro.org/lkft/linux-next-master/build/next-20220304/testrun/8235955/suite/linux-log-parser/test/check-kernel-warning-4655400/log
^ permalink raw reply [flat|nested] 8+ messages in thread
* Re: [next] WARNING: suspicious RCU usage : include/linux/cgroup.h:494 suspicious rcu_dereference_check() usage
2022-03-04 19:44 ` Paul E. McKenney
@ 2022-03-04 20:28 ` Zhouyi Zhou
2022-03-04 21:32 ` Paul E. McKenney
2022-03-05 0:57 ` [External] " Chengming Zhou
0 siblings, 2 replies; 8+ messages in thread
From: Zhouyi Zhou @ 2022-03-04 20:28 UTC (permalink / raw)
To: Paul E. McKenney
Cc: Naresh Kamboju, zhouchengming, Linux-Next Mailing List,
open list, lkft-triage, rcu, Stephen Rothwell, Peter Zijlstra,
Ingo Molnar, Will Deacon
Hi Paul
Yes, your suggestion works!
Thank you for your guidance, this is the first time I ever did a
bisection, I gained greatly during this process!
On Sat, Mar 5, 2022 at 3:44 AM Paul E. McKenney <paulmck@kernel.org> wrote:
>
> On Sat, Mar 05, 2022 at 03:38:33AM +0800, Zhouyi Zhou wrote:
> > Hi,
> > I can reproduce these warnings on my X86 VM.
> > Following the my backtrace:
> >
> > (gdb) bt
> > #0 lockdep_rcu_suspicious (file=file@entry=0xffffffff825ea8ff
> > "include/linux/cgroup.h", line=line@entry=494,
> > s=s@entry=0xffffffff825c5c50 "suspicious rcu_dereference_check()
> > usage") at ./arch/x86/include/asm/current.h:15
> > #1 0xffffffff81183103 in task_css (subsys_id=2,
> > task=0xffff888100804080) at ./include/linux/cgroup.h:494
> > #2 task_ca (tsk=0xffff888100804080) at kernel/sched/cpuacct.c:40
> > #3 cpuacct_charge (tsk=tsk@entry=0xffff888100804080,
> > cputime=cputime@entry=3344803) at kernel/sched/cpuacct.c:342
> > #4 0xffffffff81162655 in cgroup_account_cputime (delta_exec=3344803,
> > task=0xffff888100804080) at ./include/linux/cgroup.h:792
> > #5 update_curr (cfs_rq=cfs_rq@entry=0xffff88813b63f500) at
> > kernel/sched/fair.c:907
> > #6 0xffffffff81164797 in dequeue_entity (flags=10,
> > se=0xffff888100804100, cfs_rq=0xffff88813b63f500) at
> > kernel/sched/fair.c:5771
> > #7 dequeue_task_fair (rq=0xffff88813b63f440, p=0xffff888100804080,
> > flags=10) at kernel/sched/fair.c:5771
> > #8 0xffffffff8115412a in dequeue_task (flags=10,
> > p=0xffff888100804080, rq=0xffff88813b63f440) at
> > kernel/sched/core.c:2019
> > #9 __do_set_cpus_allowed (p=0xffff888100804080,
> > new_mask=0xffffffff831b4d40 <housekeeping+512>, flags=0) at
> > kernel/sched/core.c:2508
> > #10 0xffffffff811564ca in __set_cpus_allowed_ptr_locked
> > (p=p@entry=0xffff888100804080,
> > new_mask=new_mask@entry=0xffffffff831b4d40 <housekeeping+512>,
> > flags=flags@entry=0, rq=0xffff88813b63f440,
> > rf=rf@entry=0xffffc9000012bee8) at kernel/sched/core.c:2841
> > #11 0xffffffff81156573 in __set_cpus_allowed_ptr
> > (p=p@entry=0xffff888100804080, new_mask=0xffffffff831b4d40
> > <housekeeping+512>, flags=flags@entry=0)
> > at kernel/sched/core.c:2874
> > #12 0xffffffff8115664c in set_cpus_allowed_ptr
> > (p=p@entry=0xffff888100804080, new_mask=<optimized out>) at
> > kernel/sched/core.c:2879
> > #13 0xffffffff81144676 in kthreadd (unused=<optimized out>) at
> > kernel/kthread.c:724
> > #14 0xffffffff810019df in ret_from_fork () at arch/x86/entry/entry_64.S:295
> > #15 0x0000000000000000 in ?? ()
> >
> > Do the warnings have something to do with commit
> > dc6e0818bc9a0336d9accf3ea35d146d72aa7a18 (sched/cpuacct: Optimize away
> > RCU read lock) ?
>
> If you have not already done so, could you please try running on this
> commit and then on the commit immediately preceding it? Just as a
> authoritative way to answer your question. ;-)
>
> Thanx, Paul
>
git reset --hard dc6e0818bc9a0336d9accf3ea35d146d72aa7a18
make -j 16 bindeb-pkg
there are RCU WARNINGs:
http://154.223.142.244/logs/20220305/log.dc6e0818bc9a0336d9accf3ea35d146d72aa7a18.txt
then I running on the commit immediately preceding it
git reset --hard 248cc9993d1cc12b8e9ed716cc3fc09f6c3517dd
make -j 16 bindeb-pkg
the WARNINGs are gone with the wind ;-)
http://154.223.142.244/logs/20220305/log.248cc9993d1cc12b8e9ed716cc3fc09f6c3517dd.txt
Many thanks
Zhouyi
> > Many thanks
> > Zhouyi
> >
> > On Fri, Mar 4, 2022 at 10:43 PM Naresh Kamboju
> > <naresh.kamboju@linaro.org> wrote:
> > >
> > > While booting x86_64 with linux next-20220304 kernel the following kernel
> > > warning reported [1].
> > >
> > > metadata:
> > > git_ref: master
> > > git_repo: https://gitlab.com/Linaro/lkft/mirrors/next/linux-next
> > > git_sha: 6d284ba80c0c485bcaa7bdf67f232d572640edc4
> > > git_describe: next-20220304
> > > kernel-config: https://builds.tuxbuild.com/25uuYdm2vTO275aZ3IewZY5sKbU/config
> > >
> > >
> > > warning log:
> > > ---------
> > > [ 1.482171] MDS: Mitigation: Clear CPU buffers
> > > [ 1.485680] Freeing SMP alternatives memory: 52K
> > > [ 1.487341]
> > > [ 1.488169] =============================
> > > [ 1.488169] WARNING: suspicious RCU usage
> > > [ 1.488169] 5.17.0-rc6-next-20220304 #1 Not tainted
> > > [ 1.488169] -----------------------------
> > > [ 1.488169] include/linux/cgroup.h:494 suspicious
> > > rcu_dereference_check() usage!
> > > [ 1.488169]
> > > [ 1.488169] other info that might help us debug this:
> > > [ 1.488169]
> > > [ 1.488169]
> > > [ 1.488169] rcu_scheduler_active = 1, debug_locks = 1
> > > [ 1.488169] 2 locks held by kthreadd/2:
> > > [ 1.488169] #0: ffff9ba440352330 (&p->pi_lock){....}-{2:2}, at:
> > > task_rq_lock+0x2e/0x130
> > > [ 1.488169] #1: ffff9ba7a7a2d058 (&rq->__lock){-...}-{2:2}, at:
> > > task_rq_lock+0x5d/0x130
> > > [ 1.488169]
> > > [ 1.488169] stack backtrace:
> > > [ 1.488169] CPU: 0 PID: 2 Comm: kthreadd Not tainted
> > > 5.17.0-rc6-next-20220304 #1
> > > [ 1.488169] Hardware name: Supermicro SYS-5019S-ML/X11SSH-F, BIOS
> > > 2.5 11/26/2020
> > > [ 1.488169] Call Trace:
> > > [ 1.488169] <TASK>
> > > [ 1.488169] dump_stack_lvl+0x49/0x5e
> > > [ 1.488169] dump_stack+0x10/0x12
> > > [ 1.488169] lockdep_rcu_suspicious+0xed/0xf8
> > > [ 1.488169] cpuacct_charge+0x10c/0x120
> > > [ 1.488169] update_curr+0x165/0x340
> > > [ 1.488169] dequeue_entity+0x23/0x430
> > > [ 1.488169] dequeue_task_fair+0xba/0x3b0
> > > [ 1.488169] __do_set_cpus_allowed+0xca/0x2c0
> > > [ 1.488169] __set_cpus_allowed_ptr_locked+0x128/0x1b0
> > > [ 1.488169] set_cpus_allowed_ptr+0x43/0x70
> > > [ 1.488169] kthreadd+0x49/0x230
> > > [ 1.488169] ? kthread_is_per_cpu+0x30/0x30
> > > [ 1.488169] ret_from_fork+0x22/0x30
> > > [ 1.488169] </TASK>
> > > [ 1.488169]
> > > [ 1.488169] =============================
> > > [ 1.488169] WARNING: suspicious RCU usage
> > > [ 1.488169] 5.17.0-rc6-next-20220304 #1 Not tainted
> > > [ 1.488169] -----------------------------
> > > [ 1.488169] include/linux/cgroup.h:481 suspicious
> > > rcu_dereference_check() usage!
> > > [ 1.488169]
> > > [ 1.488169] other info that might help us debug this:
> > > [ 1.488169]
> > > [ 1.488169]
> > > [ 1.488169] rcu_scheduler_active = 1, debug_locks = 1
> > > [ 1.488169] 2 locks held by kthreadd/2:
> > > [ 1.488169] #0: ffff9ba440352330 (&p->pi_lock){....}-{2:2}, at:
> > > task_rq_lock+0x2e/0x130
> > > [ 1.488169] #1: ffff9ba7a7a2d058 (&rq->__lock){-...}-{2:2}, at:
> > > task_rq_lock+0x5d/0x130
> > > [ 1.488169]
> > > [ 1.488169] stack backtrace:
> > > [ 1.488169] CPU: 0 PID: 2 Comm: kthreadd Not tainted
> > > 5.17.0-rc6-next-20220304 #1
> > > [ 1.488169] Hardware name: Supermicro SYS-5019S-ML/X11SSH-F, BIOS
> > > 2.5 11/26/2020
> > > [ 1.488169] Call Trace:
> > > [ 1.488169] <TASK>
> > > [ 1.488169] dump_stack_lvl+0x49/0x5e
> > > [ 1.488169] dump_stack+0x10/0x12
> > > [ 1.488169] lockdep_rcu_suspicious+0xed/0xf8
> > > [ 1.488169] update_curr+0x2b7/0x340
> > > [ 1.488169] dequeue_entity+0x23/0x430
> > > [ 1.488169] dequeue_task_fair+0xba/0x3b0
> > > [ 1.488169] __do_set_cpus_allowed+0xca/0x2c0
> > > [ 1.488169] __set_cpus_allowed_ptr_locked+0x128/0x1b0
> > > [ 1.488169] set_cpus_allowed_ptr+0x43/0x70
> > > [ 1.488169] kthreadd+0x49/0x230
> > > [ 1.488169] ? kthread_is_per_cpu+0x30/0x30
> > > [ 1.488169] ret_from_fork+0x22/0x30
> > > [ 1.488169] </TASK>
> > > [ 1.488169]
> > > [ 1.488169] =============================
> > > [ 1.488169] WARNING: suspicious RCU usage
> > > [ 1.488169] 5.17.0-rc6-next-20220304 #1 Not tainted
> > > [ 1.488169] -----------------------------
> > > [ 1.488169] include/linux/cgroup.h:481 suspicious
> > > rcu_dereference_check() usage!
> > > [ 1.488169]
> > > [ 1.488169] other info that might help us debug this:
> > > [ 1.488169]
> > > [ 1.488169]
> > > [ 1.488169] rcu_scheduler_active = 1, debug_locks = 1
> > > [ 1.488169] no locks held by kthreadd/2.
> > > [ 1.488169]
> > > [ 1.488169] stack backtrace:
> > > [ 1.488169] CPU: 0 PID: 2 Comm: kthreadd Not tainted
> > > 5.17.0-rc6-next-20220304 #1
> > > [ 1.488169] Hardware name: Supermicro SYS-5019S-ML/X11SSH-F, BIOS
> > > 2.5 11/26/2020
> > > [ 1.488169] Call Trace:
> > > [ 1.488169] <IRQ>
> > > [ 1.488169] dump_stack_lvl+0x49/0x5e
> > > [ 1.488169] dump_stack+0x10/0x12
> > > [ 1.488169] lockdep_rcu_suspicious+0xed/0xf8
> > > [ 1.488169] account_system_index_time+0x127/0x130
> > > [ 1.488169] account_system_time+0x50/0x60
> > > [ 1.488169] account_process_tick+0x59/0x80
> > > [ 1.488169] update_process_times+0x58/0xe0
> > > [ 1.488169] tick_periodic+0x37/0xf0
> > > [ 1.488169] tick_handle_periodic+0x24/0x70
> > > [ 1.488169] timer_interrupt+0x18/0x20
> > > [ 1.488169] __handle_irq_event_percpu+0x95/0x2f0
> > > [ 1.488169] handle_irq_event+0x39/0x80
> > > [ 1.488169] handle_edge_irq+0xa4/0x240
> > > [ 1.488169] __common_interrupt+0x8d/0x170
> > > [ 1.488169] common_interrupt+0xbd/0xe0
> > > [ 1.488169] </IRQ>
> > > [ 1.488169] <TASK>
> > > [ 1.488169] asm_common_interrupt+0x1e/0x40
> > > [ 1.488169] RIP: 0010:_raw_spin_unlock_irqrestore+0x37/0x60
> > > [ 1.488169] Code: fc 48 83 c7 18 53 48 89 f3 48 8b 75 08 e8 21 83
> > > ed fe 4c 89 e7 e8 19 b0 ed fe 80 e7 02 74 06 e8 6f 77 fa fe fb bf 01
> > > 00 00 00 <e8> 24 6b e9 fe 65 8b 05 bd e1 28 66 85 c0 74 05 5b 41 5c 5d
> > > c3 0f
> > > [ 1.488169] RSP: 0000:ffffb75b0002fd50 EFLAGS: 00000202
> > > [ 1.488169] RAX: 0000000000000007 RBX: 0000000000000246 RCX: 0000000000000000
> > > [ 1.488169] RDX: 0000000000000000 RSI: ffffffff9a800a7c RDI: 0000000000000001
> > > [ 1.488169] RBP: ffffb75b0002fd60 R08: 0000000000000001 R09: 0000000000000001
> > > [ 1.488169] R10: 0000000000000002 R11: 0000000000000001 R12: ffff9ba440352318
> > > [ 1.488169] R13: 0000000000000000 R14: 0000000000000000 R15: ffff9ba7a7a2d040
> > > [ 1.488169] affine_move_task+0x2d4/0x5d0
> > > [ 1.488169] ? __this_cpu_preempt_check+0x13/0x20
> > > [ 1.488169] ? lock_is_held_type+0xdd/0x130
> > > [ 1.488169] ? enqueue_entity+0x1b8/0x520
> > > [ 1.488169] __set_cpus_allowed_ptr_locked+0x15c/0x1b0
> > > [ 1.488169] set_cpus_allowed_ptr+0x43/0x70
> > > [ 1.488169] kthreadd+0x49/0x230
> > > [ 1.488169] ? kthread_is_per_cpu+0x30/0x30
> > > [ 1.488169] ret_from_fork+0x22/0x30
> > > [ 1.488169] </TASK>
> > > [ 1.489211] smpboot: Estimated ratio of average max frequency by
> > > base frequency (times 1024): 1126
> > > [ 1.490189] smpboot: CPU0: Intel(R) Xeon(R) CPU E3-1220 v6 @
> > > 3.00GHz (family: 0x6, model: 0x9e, stepping: 0x9)
> > > [ 1.491635] cblist_init_generic: Setting adjustable number of
> > > callback queues.
> > > [ 1.492171] cblist_init_generic: Setting shift to 2 and lim to 1.
> > > [ 1.493226] cblist_init_generic: Setting shift to 2 and lim to 1.
> > > [ 1.494226] cblist_init_generic: Setting shift to 2 and lim to 1.
> > > [ 1.495219] Running RCU-tasks wait API self tests
> > > [ 1.598317] Performance Events: PEBS fmt3+, Skylake events, 32-deep
> > > LBR, full-width counters, Intel PMU driver.
> > > [ 1.599176] ... version: 4
> > > [ 1.600171] ... bit width: 48
> > > [ 1.601171] ... generic registers: 8
> > > [ 1.602171] ... value mask: 0000ffffffffffff
> > > [ 1.603171] ... max period: 00007fffffffffff
> > > [ 1.604176] ... fixed-purpose events: 3
> > > [ 1.605171] ... event mask: 00000007000000ff
> > > [ 1.606188] Callback from call_rcu_tasks_trace() invoked.
> > > [ 1.607450] rcu: Hierarchical SRCU implementation.
> > > [ 1.608310]
> > > [ 1.609169] =============================
> > > [ 1.609169] WARNING: suspicious RCU usage
> > > [ 1.609169] 5.17.0-rc6-next-20220304 #1 Not tainted
> > > [ 1.609169] -----------------------------
> > > [ 1.609169] include/linux/cgroup.h:481 suspicious
> > > rcu_dereference_check() usage!
> > > [ 1.609169]
> > > [ 1.609169] other info that might help us debug this:
> > > [ 1.609169]
> > > [ 1.609169]
> > > [ 1.609169] rcu_scheduler_active = 1, debug_locks = 1
> > > [ 1.609169] 1 lock held by migration/0/17:
> > > [ 1.609169] #0: ffff9ba7a7a2d058 (&rq->__lock){-.-.}-{2:2}, at:
> > > __schedule+0x12d/0xcb0
> > > [ 1.609169]
> > > [ 1.609169] stack backtrace:
> > > [ 1.609169] CPU: 0 PID: 17 Comm: migration/0 Not tainted
> > > 5.17.0-rc6-next-20220304 #1
> > > [ 1.609169] Hardware name: Supermicro SYS-5019S-ML/X11SSH-F, BIOS
> > > 2.5 11/26/2020
> > > [ 1.609169] Stopper: 0x0 <- 0x0
> > > [ 1.609169] Call Trace:
> > > [ 1.609169] <TASK>
> > > [ 1.609169] dump_stack_lvl+0x49/0x5e
> > > [ 1.609169] dump_stack+0x10/0x12
> > > [ 1.609169] lockdep_rcu_suspicious+0xed/0xf8
> > > [ 1.609169] put_prev_task_stop+0x1dc/0x240
> > > [ 1.609169] __schedule+0x751/0xcb0
> > > [ 1.609169] ? trace_preempt_off+0x29/0xc0
> > > [ 1.609169] ? smpboot_thread_fn+0x33/0x290
> > > [ 1.609169] schedule+0x58/0xc0
> > > [ 1.609169] smpboot_thread_fn+0xec/0x290
> > > [ 1.609169] ? sort_range+0x30/0x30
> > > [ 1.609169] kthread+0x107/0x130
> > > [ 1.609169] ? kthread_complete_and_exit+0x20/0x20
> > > [ 1.609169] ret_from_fork+0x22/0x30
> > > [ 1.609169] </TASK>
> > > [ 1.610276] smp: Bringing up secondary CPUs ...
> > > [ 1.611596] x86: Booting SMP configuration:
> > > [ 1.612179] .... node #0, CPUs: #1 #2 #3
> > > [ 1.614396] smp: Brought up 1 node, 4 CPUs
> > >
> > > Reported-by: Linux Kernel Functional Testing <lkft@linaro.org>
> > >
> > > --
> > > Linaro LKFT
> > > https://lkft.linaro.org
> > >
> > > [1] https://qa-reports.linaro.org/lkft/linux-next-master/build/next-20220304/testrun/8235955/suite/linux-log-parser/test/check-kernel-warning-4655400/log
^ permalink raw reply [flat|nested] 8+ messages in thread
* Re: [next] WARNING: suspicious RCU usage : include/linux/cgroup.h:494 suspicious rcu_dereference_check() usage
2022-03-04 20:28 ` Zhouyi Zhou
@ 2022-03-04 21:32 ` Paul E. McKenney
2022-03-05 0:57 ` [External] " Chengming Zhou
1 sibling, 0 replies; 8+ messages in thread
From: Paul E. McKenney @ 2022-03-04 21:32 UTC (permalink / raw)
To: Zhouyi Zhou
Cc: Naresh Kamboju, zhouchengming, Linux-Next Mailing List,
open list, lkft-triage, rcu, Stephen Rothwell, Peter Zijlstra,
Ingo Molnar, Will Deacon
On Sat, Mar 05, 2022 at 04:28:51AM +0800, Zhouyi Zhou wrote:
> Hi Paul
>
> Yes, your suggestion works!
> Thank you for your guidance, this is the first time I ever did a
> bisection, I gained greatly during this process!
>
> On Sat, Mar 5, 2022 at 3:44 AM Paul E. McKenney <paulmck@kernel.org> wrote:
> >
> > On Sat, Mar 05, 2022 at 03:38:33AM +0800, Zhouyi Zhou wrote:
> > > Hi,
> > > I can reproduce these warnings on my X86 VM.
> > > Following the my backtrace:
> > >
> > > (gdb) bt
> > > #0 lockdep_rcu_suspicious (file=file@entry=0xffffffff825ea8ff
> > > "include/linux/cgroup.h", line=line@entry=494,
> > > s=s@entry=0xffffffff825c5c50 "suspicious rcu_dereference_check()
> > > usage") at ./arch/x86/include/asm/current.h:15
> > > #1 0xffffffff81183103 in task_css (subsys_id=2,
> > > task=0xffff888100804080) at ./include/linux/cgroup.h:494
> > > #2 task_ca (tsk=0xffff888100804080) at kernel/sched/cpuacct.c:40
> > > #3 cpuacct_charge (tsk=tsk@entry=0xffff888100804080,
> > > cputime=cputime@entry=3344803) at kernel/sched/cpuacct.c:342
> > > #4 0xffffffff81162655 in cgroup_account_cputime (delta_exec=3344803,
> > > task=0xffff888100804080) at ./include/linux/cgroup.h:792
> > > #5 update_curr (cfs_rq=cfs_rq@entry=0xffff88813b63f500) at
> > > kernel/sched/fair.c:907
> > > #6 0xffffffff81164797 in dequeue_entity (flags=10,
> > > se=0xffff888100804100, cfs_rq=0xffff88813b63f500) at
> > > kernel/sched/fair.c:5771
> > > #7 dequeue_task_fair (rq=0xffff88813b63f440, p=0xffff888100804080,
> > > flags=10) at kernel/sched/fair.c:5771
> > > #8 0xffffffff8115412a in dequeue_task (flags=10,
> > > p=0xffff888100804080, rq=0xffff88813b63f440) at
> > > kernel/sched/core.c:2019
> > > #9 __do_set_cpus_allowed (p=0xffff888100804080,
> > > new_mask=0xffffffff831b4d40 <housekeeping+512>, flags=0) at
> > > kernel/sched/core.c:2508
> > > #10 0xffffffff811564ca in __set_cpus_allowed_ptr_locked
> > > (p=p@entry=0xffff888100804080,
> > > new_mask=new_mask@entry=0xffffffff831b4d40 <housekeeping+512>,
> > > flags=flags@entry=0, rq=0xffff88813b63f440,
> > > rf=rf@entry=0xffffc9000012bee8) at kernel/sched/core.c:2841
> > > #11 0xffffffff81156573 in __set_cpus_allowed_ptr
> > > (p=p@entry=0xffff888100804080, new_mask=0xffffffff831b4d40
> > > <housekeeping+512>, flags=flags@entry=0)
> > > at kernel/sched/core.c:2874
> > > #12 0xffffffff8115664c in set_cpus_allowed_ptr
> > > (p=p@entry=0xffff888100804080, new_mask=<optimized out>) at
> > > kernel/sched/core.c:2879
> > > #13 0xffffffff81144676 in kthreadd (unused=<optimized out>) at
> > > kernel/kthread.c:724
> > > #14 0xffffffff810019df in ret_from_fork () at arch/x86/entry/entry_64.S:295
> > > #15 0x0000000000000000 in ?? ()
> > >
> > > Do the warnings have something to do with commit
> > > dc6e0818bc9a0336d9accf3ea35d146d72aa7a18 (sched/cpuacct: Optimize away
> > > RCU read lock) ?
> >
> > If you have not already done so, could you please try running on this
> > commit and then on the commit immediately preceding it? Just as a
> > authoritative way to answer your question. ;-)
> >
> > Thanx, Paul
> >
> git reset --hard dc6e0818bc9a0336d9accf3ea35d146d72aa7a18
> make -j 16 bindeb-pkg
> there are RCU WARNINGs:
> http://154.223.142.244/logs/20220305/log.dc6e0818bc9a0336d9accf3ea35d146d72aa7a18.txt
>
> then I running on the commit immediately preceding it
> git reset --hard 248cc9993d1cc12b8e9ed716cc3fc09f6c3517dd
> make -j 16 bindeb-pkg
> the WARNINGs are gone with the wind ;-)
> http://154.223.142.244/logs/20220305/log.248cc9993d1cc12b8e9ed716cc3fc09f6c3517dd.txt
That does look convincing. ;-)
Adding that patch's author, Chengming Zhou, on CC. (Feel free to do
this yourself next time around.)
Thanx, Paul
> Many thanks
> Zhouyi
> > > Many thanks
> > > Zhouyi
> > >
> > > On Fri, Mar 4, 2022 at 10:43 PM Naresh Kamboju
> > > <naresh.kamboju@linaro.org> wrote:
> > > >
> > > > While booting x86_64 with linux next-20220304 kernel the following kernel
> > > > warning reported [1].
> > > >
> > > > metadata:
> > > > git_ref: master
> > > > git_repo: https://gitlab.com/Linaro/lkft/mirrors/next/linux-next
> > > > git_sha: 6d284ba80c0c485bcaa7bdf67f232d572640edc4
> > > > git_describe: next-20220304
> > > > kernel-config: https://builds.tuxbuild.com/25uuYdm2vTO275aZ3IewZY5sKbU/config
> > > >
> > > >
> > > > warning log:
> > > > ---------
> > > > [ 1.482171] MDS: Mitigation: Clear CPU buffers
> > > > [ 1.485680] Freeing SMP alternatives memory: 52K
> > > > [ 1.487341]
> > > > [ 1.488169] =============================
> > > > [ 1.488169] WARNING: suspicious RCU usage
> > > > [ 1.488169] 5.17.0-rc6-next-20220304 #1 Not tainted
> > > > [ 1.488169] -----------------------------
> > > > [ 1.488169] include/linux/cgroup.h:494 suspicious
> > > > rcu_dereference_check() usage!
> > > > [ 1.488169]
> > > > [ 1.488169] other info that might help us debug this:
> > > > [ 1.488169]
> > > > [ 1.488169]
> > > > [ 1.488169] rcu_scheduler_active = 1, debug_locks = 1
> > > > [ 1.488169] 2 locks held by kthreadd/2:
> > > > [ 1.488169] #0: ffff9ba440352330 (&p->pi_lock){....}-{2:2}, at:
> > > > task_rq_lock+0x2e/0x130
> > > > [ 1.488169] #1: ffff9ba7a7a2d058 (&rq->__lock){-...}-{2:2}, at:
> > > > task_rq_lock+0x5d/0x130
> > > > [ 1.488169]
> > > > [ 1.488169] stack backtrace:
> > > > [ 1.488169] CPU: 0 PID: 2 Comm: kthreadd Not tainted
> > > > 5.17.0-rc6-next-20220304 #1
> > > > [ 1.488169] Hardware name: Supermicro SYS-5019S-ML/X11SSH-F, BIOS
> > > > 2.5 11/26/2020
> > > > [ 1.488169] Call Trace:
> > > > [ 1.488169] <TASK>
> > > > [ 1.488169] dump_stack_lvl+0x49/0x5e
> > > > [ 1.488169] dump_stack+0x10/0x12
> > > > [ 1.488169] lockdep_rcu_suspicious+0xed/0xf8
> > > > [ 1.488169] cpuacct_charge+0x10c/0x120
> > > > [ 1.488169] update_curr+0x165/0x340
> > > > [ 1.488169] dequeue_entity+0x23/0x430
> > > > [ 1.488169] dequeue_task_fair+0xba/0x3b0
> > > > [ 1.488169] __do_set_cpus_allowed+0xca/0x2c0
> > > > [ 1.488169] __set_cpus_allowed_ptr_locked+0x128/0x1b0
> > > > [ 1.488169] set_cpus_allowed_ptr+0x43/0x70
> > > > [ 1.488169] kthreadd+0x49/0x230
> > > > [ 1.488169] ? kthread_is_per_cpu+0x30/0x30
> > > > [ 1.488169] ret_from_fork+0x22/0x30
> > > > [ 1.488169] </TASK>
> > > > [ 1.488169]
> > > > [ 1.488169] =============================
> > > > [ 1.488169] WARNING: suspicious RCU usage
> > > > [ 1.488169] 5.17.0-rc6-next-20220304 #1 Not tainted
> > > > [ 1.488169] -----------------------------
> > > > [ 1.488169] include/linux/cgroup.h:481 suspicious
> > > > rcu_dereference_check() usage!
> > > > [ 1.488169]
> > > > [ 1.488169] other info that might help us debug this:
> > > > [ 1.488169]
> > > > [ 1.488169]
> > > > [ 1.488169] rcu_scheduler_active = 1, debug_locks = 1
> > > > [ 1.488169] 2 locks held by kthreadd/2:
> > > > [ 1.488169] #0: ffff9ba440352330 (&p->pi_lock){....}-{2:2}, at:
> > > > task_rq_lock+0x2e/0x130
> > > > [ 1.488169] #1: ffff9ba7a7a2d058 (&rq->__lock){-...}-{2:2}, at:
> > > > task_rq_lock+0x5d/0x130
> > > > [ 1.488169]
> > > > [ 1.488169] stack backtrace:
> > > > [ 1.488169] CPU: 0 PID: 2 Comm: kthreadd Not tainted
> > > > 5.17.0-rc6-next-20220304 #1
> > > > [ 1.488169] Hardware name: Supermicro SYS-5019S-ML/X11SSH-F, BIOS
> > > > 2.5 11/26/2020
> > > > [ 1.488169] Call Trace:
> > > > [ 1.488169] <TASK>
> > > > [ 1.488169] dump_stack_lvl+0x49/0x5e
> > > > [ 1.488169] dump_stack+0x10/0x12
> > > > [ 1.488169] lockdep_rcu_suspicious+0xed/0xf8
> > > > [ 1.488169] update_curr+0x2b7/0x340
> > > > [ 1.488169] dequeue_entity+0x23/0x430
> > > > [ 1.488169] dequeue_task_fair+0xba/0x3b0
> > > > [ 1.488169] __do_set_cpus_allowed+0xca/0x2c0
> > > > [ 1.488169] __set_cpus_allowed_ptr_locked+0x128/0x1b0
> > > > [ 1.488169] set_cpus_allowed_ptr+0x43/0x70
> > > > [ 1.488169] kthreadd+0x49/0x230
> > > > [ 1.488169] ? kthread_is_per_cpu+0x30/0x30
> > > > [ 1.488169] ret_from_fork+0x22/0x30
> > > > [ 1.488169] </TASK>
> > > > [ 1.488169]
> > > > [ 1.488169] =============================
> > > > [ 1.488169] WARNING: suspicious RCU usage
> > > > [ 1.488169] 5.17.0-rc6-next-20220304 #1 Not tainted
> > > > [ 1.488169] -----------------------------
> > > > [ 1.488169] include/linux/cgroup.h:481 suspicious
> > > > rcu_dereference_check() usage!
> > > > [ 1.488169]
> > > > [ 1.488169] other info that might help us debug this:
> > > > [ 1.488169]
> > > > [ 1.488169]
> > > > [ 1.488169] rcu_scheduler_active = 1, debug_locks = 1
> > > > [ 1.488169] no locks held by kthreadd/2.
> > > > [ 1.488169]
> > > > [ 1.488169] stack backtrace:
> > > > [ 1.488169] CPU: 0 PID: 2 Comm: kthreadd Not tainted
> > > > 5.17.0-rc6-next-20220304 #1
> > > > [ 1.488169] Hardware name: Supermicro SYS-5019S-ML/X11SSH-F, BIOS
> > > > 2.5 11/26/2020
> > > > [ 1.488169] Call Trace:
> > > > [ 1.488169] <IRQ>
> > > > [ 1.488169] dump_stack_lvl+0x49/0x5e
> > > > [ 1.488169] dump_stack+0x10/0x12
> > > > [ 1.488169] lockdep_rcu_suspicious+0xed/0xf8
> > > > [ 1.488169] account_system_index_time+0x127/0x130
> > > > [ 1.488169] account_system_time+0x50/0x60
> > > > [ 1.488169] account_process_tick+0x59/0x80
> > > > [ 1.488169] update_process_times+0x58/0xe0
> > > > [ 1.488169] tick_periodic+0x37/0xf0
> > > > [ 1.488169] tick_handle_periodic+0x24/0x70
> > > > [ 1.488169] timer_interrupt+0x18/0x20
> > > > [ 1.488169] __handle_irq_event_percpu+0x95/0x2f0
> > > > [ 1.488169] handle_irq_event+0x39/0x80
> > > > [ 1.488169] handle_edge_irq+0xa4/0x240
> > > > [ 1.488169] __common_interrupt+0x8d/0x170
> > > > [ 1.488169] common_interrupt+0xbd/0xe0
> > > > [ 1.488169] </IRQ>
> > > > [ 1.488169] <TASK>
> > > > [ 1.488169] asm_common_interrupt+0x1e/0x40
> > > > [ 1.488169] RIP: 0010:_raw_spin_unlock_irqrestore+0x37/0x60
> > > > [ 1.488169] Code: fc 48 83 c7 18 53 48 89 f3 48 8b 75 08 e8 21 83
> > > > ed fe 4c 89 e7 e8 19 b0 ed fe 80 e7 02 74 06 e8 6f 77 fa fe fb bf 01
> > > > 00 00 00 <e8> 24 6b e9 fe 65 8b 05 bd e1 28 66 85 c0 74 05 5b 41 5c 5d
> > > > c3 0f
> > > > [ 1.488169] RSP: 0000:ffffb75b0002fd50 EFLAGS: 00000202
> > > > [ 1.488169] RAX: 0000000000000007 RBX: 0000000000000246 RCX: 0000000000000000
> > > > [ 1.488169] RDX: 0000000000000000 RSI: ffffffff9a800a7c RDI: 0000000000000001
> > > > [ 1.488169] RBP: ffffb75b0002fd60 R08: 0000000000000001 R09: 0000000000000001
> > > > [ 1.488169] R10: 0000000000000002 R11: 0000000000000001 R12: ffff9ba440352318
> > > > [ 1.488169] R13: 0000000000000000 R14: 0000000000000000 R15: ffff9ba7a7a2d040
> > > > [ 1.488169] affine_move_task+0x2d4/0x5d0
> > > > [ 1.488169] ? __this_cpu_preempt_check+0x13/0x20
> > > > [ 1.488169] ? lock_is_held_type+0xdd/0x130
> > > > [ 1.488169] ? enqueue_entity+0x1b8/0x520
> > > > [ 1.488169] __set_cpus_allowed_ptr_locked+0x15c/0x1b0
> > > > [ 1.488169] set_cpus_allowed_ptr+0x43/0x70
> > > > [ 1.488169] kthreadd+0x49/0x230
> > > > [ 1.488169] ? kthread_is_per_cpu+0x30/0x30
> > > > [ 1.488169] ret_from_fork+0x22/0x30
> > > > [ 1.488169] </TASK>
> > > > [ 1.489211] smpboot: Estimated ratio of average max frequency by
> > > > base frequency (times 1024): 1126
> > > > [ 1.490189] smpboot: CPU0: Intel(R) Xeon(R) CPU E3-1220 v6 @
> > > > 3.00GHz (family: 0x6, model: 0x9e, stepping: 0x9)
> > > > [ 1.491635] cblist_init_generic: Setting adjustable number of
> > > > callback queues.
> > > > [ 1.492171] cblist_init_generic: Setting shift to 2 and lim to 1.
> > > > [ 1.493226] cblist_init_generic: Setting shift to 2 and lim to 1.
> > > > [ 1.494226] cblist_init_generic: Setting shift to 2 and lim to 1.
> > > > [ 1.495219] Running RCU-tasks wait API self tests
> > > > [ 1.598317] Performance Events: PEBS fmt3+, Skylake events, 32-deep
> > > > LBR, full-width counters, Intel PMU driver.
> > > > [ 1.599176] ... version: 4
> > > > [ 1.600171] ... bit width: 48
> > > > [ 1.601171] ... generic registers: 8
> > > > [ 1.602171] ... value mask: 0000ffffffffffff
> > > > [ 1.603171] ... max period: 00007fffffffffff
> > > > [ 1.604176] ... fixed-purpose events: 3
> > > > [ 1.605171] ... event mask: 00000007000000ff
> > > > [ 1.606188] Callback from call_rcu_tasks_trace() invoked.
> > > > [ 1.607450] rcu: Hierarchical SRCU implementation.
> > > > [ 1.608310]
> > > > [ 1.609169] =============================
> > > > [ 1.609169] WARNING: suspicious RCU usage
> > > > [ 1.609169] 5.17.0-rc6-next-20220304 #1 Not tainted
> > > > [ 1.609169] -----------------------------
> > > > [ 1.609169] include/linux/cgroup.h:481 suspicious
> > > > rcu_dereference_check() usage!
> > > > [ 1.609169]
> > > > [ 1.609169] other info that might help us debug this:
> > > > [ 1.609169]
> > > > [ 1.609169]
> > > > [ 1.609169] rcu_scheduler_active = 1, debug_locks = 1
> > > > [ 1.609169] 1 lock held by migration/0/17:
> > > > [ 1.609169] #0: ffff9ba7a7a2d058 (&rq->__lock){-.-.}-{2:2}, at:
> > > > __schedule+0x12d/0xcb0
> > > > [ 1.609169]
> > > > [ 1.609169] stack backtrace:
> > > > [ 1.609169] CPU: 0 PID: 17 Comm: migration/0 Not tainted
> > > > 5.17.0-rc6-next-20220304 #1
> > > > [ 1.609169] Hardware name: Supermicro SYS-5019S-ML/X11SSH-F, BIOS
> > > > 2.5 11/26/2020
> > > > [ 1.609169] Stopper: 0x0 <- 0x0
> > > > [ 1.609169] Call Trace:
> > > > [ 1.609169] <TASK>
> > > > [ 1.609169] dump_stack_lvl+0x49/0x5e
> > > > [ 1.609169] dump_stack+0x10/0x12
> > > > [ 1.609169] lockdep_rcu_suspicious+0xed/0xf8
> > > > [ 1.609169] put_prev_task_stop+0x1dc/0x240
> > > > [ 1.609169] __schedule+0x751/0xcb0
> > > > [ 1.609169] ? trace_preempt_off+0x29/0xc0
> > > > [ 1.609169] ? smpboot_thread_fn+0x33/0x290
> > > > [ 1.609169] schedule+0x58/0xc0
> > > > [ 1.609169] smpboot_thread_fn+0xec/0x290
> > > > [ 1.609169] ? sort_range+0x30/0x30
> > > > [ 1.609169] kthread+0x107/0x130
> > > > [ 1.609169] ? kthread_complete_and_exit+0x20/0x20
> > > > [ 1.609169] ret_from_fork+0x22/0x30
> > > > [ 1.609169] </TASK>
> > > > [ 1.610276] smp: Bringing up secondary CPUs ...
> > > > [ 1.611596] x86: Booting SMP configuration:
> > > > [ 1.612179] .... node #0, CPUs: #1 #2 #3
> > > > [ 1.614396] smp: Brought up 1 node, 4 CPUs
> > > >
> > > > Reported-by: Linux Kernel Functional Testing <lkft@linaro.org>
> > > >
> > > > --
> > > > Linaro LKFT
> > > > https://lkft.linaro.org
> > > >
> > > > [1] https://qa-reports.linaro.org/lkft/linux-next-master/build/next-20220304/testrun/8235955/suite/linux-log-parser/test/check-kernel-warning-4655400/log
^ permalink raw reply [flat|nested] 8+ messages in thread
* Re: [External] Re: [next] WARNING: suspicious RCU usage : include/linux/cgroup.h:494 suspicious rcu_dereference_check() usage
2022-03-04 20:28 ` Zhouyi Zhou
2022-03-04 21:32 ` Paul E. McKenney
@ 2022-03-05 0:57 ` Chengming Zhou
2022-03-05 1:47 ` Zhouyi Zhou
2022-03-07 5:54 ` Naresh Kamboju
1 sibling, 2 replies; 8+ messages in thread
From: Chengming Zhou @ 2022-03-05 0:57 UTC (permalink / raw)
To: Zhouyi Zhou, Paul E. McKenney
Cc: Naresh Kamboju, Linux-Next Mailing List, open list, lkft-triage,
rcu, Stephen Rothwell, Peter Zijlstra, Ingo Molnar, Will Deacon
On 2022/3/5 4:28 上午, Zhouyi Zhou wrote:
> Hi Paul
>
> Yes, your suggestion works!
> Thank you for your guidance, this is the first time I ever did a
> bisection, I gained greatly during this process!
Hi Zhouyi, thanks for the bisection test.
Could this patch solve RCU warning? I just tested on my machine and there
is no RCU warning any more.
diff --git a/include/linux/cgroup.h b/include/linux/cgroup.h
index 1e356c222756..0d1ada8968d7 100644
--- a/include/linux/cgroup.h
+++ b/include/linux/cgroup.h
@@ -450,6 +450,7 @@ extern struct mutex cgroup_mutex;
extern spinlock_t css_set_lock;
#define task_css_set_check(task, __c) \
rcu_dereference_check((task)->cgroups, \
+ rcu_read_lock_sched_held() || \
lockdep_is_held(&cgroup_mutex) || \
lockdep_is_held(&css_set_lock) || \
((task)->flags & PF_EXITING) || (__c))
Thanks.
>
> On Sat, Mar 5, 2022 at 3:44 AM Paul E. McKenney <paulmck@kernel.org> wrote:
>>
>> On Sat, Mar 05, 2022 at 03:38:33AM +0800, Zhouyi Zhou wrote:
>>> Hi,
>>> I can reproduce these warnings on my X86 VM.
>>> Following the my backtrace:
>>>
>>> (gdb) bt
>>> #0 lockdep_rcu_suspicious (file=file@entry=0xffffffff825ea8ff
>>> "include/linux/cgroup.h", line=line@entry=494,
>>> s=s@entry=0xffffffff825c5c50 "suspicious rcu_dereference_check()
>>> usage") at ./arch/x86/include/asm/current.h:15
>>> #1 0xffffffff81183103 in task_css (subsys_id=2,
>>> task=0xffff888100804080) at ./include/linux/cgroup.h:494
>>> #2 task_ca (tsk=0xffff888100804080) at kernel/sched/cpuacct.c:40
>>> #3 cpuacct_charge (tsk=tsk@entry=0xffff888100804080,
>>> cputime=cputime@entry=3344803) at kernel/sched/cpuacct.c:342
>>> #4 0xffffffff81162655 in cgroup_account_cputime (delta_exec=3344803,
>>> task=0xffff888100804080) at ./include/linux/cgroup.h:792
>>> #5 update_curr (cfs_rq=cfs_rq@entry=0xffff88813b63f500) at
>>> kernel/sched/fair.c:907
>>> #6 0xffffffff81164797 in dequeue_entity (flags=10,
>>> se=0xffff888100804100, cfs_rq=0xffff88813b63f500) at
>>> kernel/sched/fair.c:5771
>>> #7 dequeue_task_fair (rq=0xffff88813b63f440, p=0xffff888100804080,
>>> flags=10) at kernel/sched/fair.c:5771
>>> #8 0xffffffff8115412a in dequeue_task (flags=10,
>>> p=0xffff888100804080, rq=0xffff88813b63f440) at
>>> kernel/sched/core.c:2019
>>> #9 __do_set_cpus_allowed (p=0xffff888100804080,
>>> new_mask=0xffffffff831b4d40 <housekeeping+512>, flags=0) at
>>> kernel/sched/core.c:2508
>>> #10 0xffffffff811564ca in __set_cpus_allowed_ptr_locked
>>> (p=p@entry=0xffff888100804080,
>>> new_mask=new_mask@entry=0xffffffff831b4d40 <housekeeping+512>,
>>> flags=flags@entry=0, rq=0xffff88813b63f440,
>>> rf=rf@entry=0xffffc9000012bee8) at kernel/sched/core.c:2841
>>> #11 0xffffffff81156573 in __set_cpus_allowed_ptr
>>> (p=p@entry=0xffff888100804080, new_mask=0xffffffff831b4d40
>>> <housekeeping+512>, flags=flags@entry=0)
>>> at kernel/sched/core.c:2874
>>> #12 0xffffffff8115664c in set_cpus_allowed_ptr
>>> (p=p@entry=0xffff888100804080, new_mask=<optimized out>) at
>>> kernel/sched/core.c:2879
>>> #13 0xffffffff81144676 in kthreadd (unused=<optimized out>) at
>>> kernel/kthread.c:724
>>> #14 0xffffffff810019df in ret_from_fork () at arch/x86/entry/entry_64.S:295
>>> #15 0x0000000000000000 in ?? ()
>>>
>>> Do the warnings have something to do with commit
>>> dc6e0818bc9a0336d9accf3ea35d146d72aa7a18 (sched/cpuacct: Optimize away
>>> RCU read lock) ?
>>
>> If you have not already done so, could you please try running on this
>> commit and then on the commit immediately preceding it? Just as a
>> authoritative way to answer your question. ;-)
>>
>> Thanx, Paul
>>
> git reset --hard dc6e0818bc9a0336d9accf3ea35d146d72aa7a18
> make -j 16 bindeb-pkg
> there are RCU WARNINGs:
> http://154.223.142.244/logs/20220305/log.dc6e0818bc9a0336d9accf3ea35d146d72aa7a18.txt
>
> then I running on the commit immediately preceding it
> git reset --hard 248cc9993d1cc12b8e9ed716cc3fc09f6c3517dd
> make -j 16 bindeb-pkg
> the WARNINGs are gone with the wind ;-)
> http://154.223.142.244/logs/20220305/log.248cc9993d1cc12b8e9ed716cc3fc09f6c3517dd.txt
>
> Many thanks
> Zhouyi
>>> Many thanks
>>> Zhouyi
>>>
>>> On Fri, Mar 4, 2022 at 10:43 PM Naresh Kamboju
>>> <naresh.kamboju@linaro.org> wrote:
>>>>
>>>> While booting x86_64 with linux next-20220304 kernel the following kernel
>>>> warning reported [1].
>>>>
>>>> metadata:
>>>> git_ref: master
>>>> git_repo: https://gitlab.com/Linaro/lkft/mirrors/next/linux-next
>>>> git_sha: 6d284ba80c0c485bcaa7bdf67f232d572640edc4
>>>> git_describe: next-20220304
>>>> kernel-config: https://builds.tuxbuild.com/25uuYdm2vTO275aZ3IewZY5sKbU/config
>>>>
>>>>
>>>> warning log:
>>>> ---------
>>>> [ 1.482171] MDS: Mitigation: Clear CPU buffers
>>>> [ 1.485680] Freeing SMP alternatives memory: 52K
>>>> [ 1.487341]
>>>> [ 1.488169] =============================
>>>> [ 1.488169] WARNING: suspicious RCU usage
>>>> [ 1.488169] 5.17.0-rc6-next-20220304 #1 Not tainted
>>>> [ 1.488169] -----------------------------
>>>> [ 1.488169] include/linux/cgroup.h:494 suspicious
>>>> rcu_dereference_check() usage!
>>>> [ 1.488169]
>>>> [ 1.488169] other info that might help us debug this:
>>>> [ 1.488169]
>>>> [ 1.488169]
>>>> [ 1.488169] rcu_scheduler_active = 1, debug_locks = 1
>>>> [ 1.488169] 2 locks held by kthreadd/2:
>>>> [ 1.488169] #0: ffff9ba440352330 (&p->pi_lock){....}-{2:2}, at:
>>>> task_rq_lock+0x2e/0x130
>>>> [ 1.488169] #1: ffff9ba7a7a2d058 (&rq->__lock){-...}-{2:2}, at:
>>>> task_rq_lock+0x5d/0x130
>>>> [ 1.488169]
>>>> [ 1.488169] stack backtrace:
>>>> [ 1.488169] CPU: 0 PID: 2 Comm: kthreadd Not tainted
>>>> 5.17.0-rc6-next-20220304 #1
>>>> [ 1.488169] Hardware name: Supermicro SYS-5019S-ML/X11SSH-F, BIOS
>>>> 2.5 11/26/2020
>>>> [ 1.488169] Call Trace:
>>>> [ 1.488169] <TASK>
>>>> [ 1.488169] dump_stack_lvl+0x49/0x5e
>>>> [ 1.488169] dump_stack+0x10/0x12
>>>> [ 1.488169] lockdep_rcu_suspicious+0xed/0xf8
>>>> [ 1.488169] cpuacct_charge+0x10c/0x120
>>>> [ 1.488169] update_curr+0x165/0x340
>>>> [ 1.488169] dequeue_entity+0x23/0x430
>>>> [ 1.488169] dequeue_task_fair+0xba/0x3b0
>>>> [ 1.488169] __do_set_cpus_allowed+0xca/0x2c0
>>>> [ 1.488169] __set_cpus_allowed_ptr_locked+0x128/0x1b0
>>>> [ 1.488169] set_cpus_allowed_ptr+0x43/0x70
>>>> [ 1.488169] kthreadd+0x49/0x230
>>>> [ 1.488169] ? kthread_is_per_cpu+0x30/0x30
>>>> [ 1.488169] ret_from_fork+0x22/0x30
>>>> [ 1.488169] </TASK>
>>>> [ 1.488169]
>>>> [ 1.488169] =============================
>>>> [ 1.488169] WARNING: suspicious RCU usage
>>>> [ 1.488169] 5.17.0-rc6-next-20220304 #1 Not tainted
>>>> [ 1.488169] -----------------------------
>>>> [ 1.488169] include/linux/cgroup.h:481 suspicious
>>>> rcu_dereference_check() usage!
>>>> [ 1.488169]
>>>> [ 1.488169] other info that might help us debug this:
>>>> [ 1.488169]
>>>> [ 1.488169]
>>>> [ 1.488169] rcu_scheduler_active = 1, debug_locks = 1
>>>> [ 1.488169] 2 locks held by kthreadd/2:
>>>> [ 1.488169] #0: ffff9ba440352330 (&p->pi_lock){....}-{2:2}, at:
>>>> task_rq_lock+0x2e/0x130
>>>> [ 1.488169] #1: ffff9ba7a7a2d058 (&rq->__lock){-...}-{2:2}, at:
>>>> task_rq_lock+0x5d/0x130
>>>> [ 1.488169]
>>>> [ 1.488169] stack backtrace:
>>>> [ 1.488169] CPU: 0 PID: 2 Comm: kthreadd Not tainted
>>>> 5.17.0-rc6-next-20220304 #1
>>>> [ 1.488169] Hardware name: Supermicro SYS-5019S-ML/X11SSH-F, BIOS
>>>> 2.5 11/26/2020
>>>> [ 1.488169] Call Trace:
>>>> [ 1.488169] <TASK>
>>>> [ 1.488169] dump_stack_lvl+0x49/0x5e
>>>> [ 1.488169] dump_stack+0x10/0x12
>>>> [ 1.488169] lockdep_rcu_suspicious+0xed/0xf8
>>>> [ 1.488169] update_curr+0x2b7/0x340
>>>> [ 1.488169] dequeue_entity+0x23/0x430
>>>> [ 1.488169] dequeue_task_fair+0xba/0x3b0
>>>> [ 1.488169] __do_set_cpus_allowed+0xca/0x2c0
>>>> [ 1.488169] __set_cpus_allowed_ptr_locked+0x128/0x1b0
>>>> [ 1.488169] set_cpus_allowed_ptr+0x43/0x70
>>>> [ 1.488169] kthreadd+0x49/0x230
>>>> [ 1.488169] ? kthread_is_per_cpu+0x30/0x30
>>>> [ 1.488169] ret_from_fork+0x22/0x30
>>>> [ 1.488169] </TASK>
>>>> [ 1.488169]
>>>> [ 1.488169] =============================
>>>> [ 1.488169] WARNING: suspicious RCU usage
>>>> [ 1.488169] 5.17.0-rc6-next-20220304 #1 Not tainted
>>>> [ 1.488169] -----------------------------
>>>> [ 1.488169] include/linux/cgroup.h:481 suspicious
>>>> rcu_dereference_check() usage!
>>>> [ 1.488169]
>>>> [ 1.488169] other info that might help us debug this:
>>>> [ 1.488169]
>>>> [ 1.488169]
>>>> [ 1.488169] rcu_scheduler_active = 1, debug_locks = 1
>>>> [ 1.488169] no locks held by kthreadd/2.
>>>> [ 1.488169]
>>>> [ 1.488169] stack backtrace:
>>>> [ 1.488169] CPU: 0 PID: 2 Comm: kthreadd Not tainted
>>>> 5.17.0-rc6-next-20220304 #1
>>>> [ 1.488169] Hardware name: Supermicro SYS-5019S-ML/X11SSH-F, BIOS
>>>> 2.5 11/26/2020
>>>> [ 1.488169] Call Trace:
>>>> [ 1.488169] <IRQ>
>>>> [ 1.488169] dump_stack_lvl+0x49/0x5e
>>>> [ 1.488169] dump_stack+0x10/0x12
>>>> [ 1.488169] lockdep_rcu_suspicious+0xed/0xf8
>>>> [ 1.488169] account_system_index_time+0x127/0x130
>>>> [ 1.488169] account_system_time+0x50/0x60
>>>> [ 1.488169] account_process_tick+0x59/0x80
>>>> [ 1.488169] update_process_times+0x58/0xe0
>>>> [ 1.488169] tick_periodic+0x37/0xf0
>>>> [ 1.488169] tick_handle_periodic+0x24/0x70
>>>> [ 1.488169] timer_interrupt+0x18/0x20
>>>> [ 1.488169] __handle_irq_event_percpu+0x95/0x2f0
>>>> [ 1.488169] handle_irq_event+0x39/0x80
>>>> [ 1.488169] handle_edge_irq+0xa4/0x240
>>>> [ 1.488169] __common_interrupt+0x8d/0x170
>>>> [ 1.488169] common_interrupt+0xbd/0xe0
>>>> [ 1.488169] </IRQ>
>>>> [ 1.488169] <TASK>
>>>> [ 1.488169] asm_common_interrupt+0x1e/0x40
>>>> [ 1.488169] RIP: 0010:_raw_spin_unlock_irqrestore+0x37/0x60
>>>> [ 1.488169] Code: fc 48 83 c7 18 53 48 89 f3 48 8b 75 08 e8 21 83
>>>> ed fe 4c 89 e7 e8 19 b0 ed fe 80 e7 02 74 06 e8 6f 77 fa fe fb bf 01
>>>> 00 00 00 <e8> 24 6b e9 fe 65 8b 05 bd e1 28 66 85 c0 74 05 5b 41 5c 5d
>>>> c3 0f
>>>> [ 1.488169] RSP: 0000:ffffb75b0002fd50 EFLAGS: 00000202
>>>> [ 1.488169] RAX: 0000000000000007 RBX: 0000000000000246 RCX: 0000000000000000
>>>> [ 1.488169] RDX: 0000000000000000 RSI: ffffffff9a800a7c RDI: 0000000000000001
>>>> [ 1.488169] RBP: ffffb75b0002fd60 R08: 0000000000000001 R09: 0000000000000001
>>>> [ 1.488169] R10: 0000000000000002 R11: 0000000000000001 R12: ffff9ba440352318
>>>> [ 1.488169] R13: 0000000000000000 R14: 0000000000000000 R15: ffff9ba7a7a2d040
>>>> [ 1.488169] affine_move_task+0x2d4/0x5d0
>>>> [ 1.488169] ? __this_cpu_preempt_check+0x13/0x20
>>>> [ 1.488169] ? lock_is_held_type+0xdd/0x130
>>>> [ 1.488169] ? enqueue_entity+0x1b8/0x520
>>>> [ 1.488169] __set_cpus_allowed_ptr_locked+0x15c/0x1b0
>>>> [ 1.488169] set_cpus_allowed_ptr+0x43/0x70
>>>> [ 1.488169] kthreadd+0x49/0x230
>>>> [ 1.488169] ? kthread_is_per_cpu+0x30/0x30
>>>> [ 1.488169] ret_from_fork+0x22/0x30
>>>> [ 1.488169] </TASK>
>>>> [ 1.489211] smpboot: Estimated ratio of average max frequency by
>>>> base frequency (times 1024): 1126
>>>> [ 1.490189] smpboot: CPU0: Intel(R) Xeon(R) CPU E3-1220 v6 @
>>>> 3.00GHz (family: 0x6, model: 0x9e, stepping: 0x9)
>>>> [ 1.491635] cblist_init_generic: Setting adjustable number of
>>>> callback queues.
>>>> [ 1.492171] cblist_init_generic: Setting shift to 2 and lim to 1.
>>>> [ 1.493226] cblist_init_generic: Setting shift to 2 and lim to 1.
>>>> [ 1.494226] cblist_init_generic: Setting shift to 2 and lim to 1.
>>>> [ 1.495219] Running RCU-tasks wait API self tests
>>>> [ 1.598317] Performance Events: PEBS fmt3+, Skylake events, 32-deep
>>>> LBR, full-width counters, Intel PMU driver.
>>>> [ 1.599176] ... version: 4
>>>> [ 1.600171] ... bit width: 48
>>>> [ 1.601171] ... generic registers: 8
>>>> [ 1.602171] ... value mask: 0000ffffffffffff
>>>> [ 1.603171] ... max period: 00007fffffffffff
>>>> [ 1.604176] ... fixed-purpose events: 3
>>>> [ 1.605171] ... event mask: 00000007000000ff
>>>> [ 1.606188] Callback from call_rcu_tasks_trace() invoked.
>>>> [ 1.607450] rcu: Hierarchical SRCU implementation.
>>>> [ 1.608310]
>>>> [ 1.609169] =============================
>>>> [ 1.609169] WARNING: suspicious RCU usage
>>>> [ 1.609169] 5.17.0-rc6-next-20220304 #1 Not tainted
>>>> [ 1.609169] -----------------------------
>>>> [ 1.609169] include/linux/cgroup.h:481 suspicious
>>>> rcu_dereference_check() usage!
>>>> [ 1.609169]
>>>> [ 1.609169] other info that might help us debug this:
>>>> [ 1.609169]
>>>> [ 1.609169]
>>>> [ 1.609169] rcu_scheduler_active = 1, debug_locks = 1
>>>> [ 1.609169] 1 lock held by migration/0/17:
>>>> [ 1.609169] #0: ffff9ba7a7a2d058 (&rq->__lock){-.-.}-{2:2}, at:
>>>> __schedule+0x12d/0xcb0
>>>> [ 1.609169]
>>>> [ 1.609169] stack backtrace:
>>>> [ 1.609169] CPU: 0 PID: 17 Comm: migration/0 Not tainted
>>>> 5.17.0-rc6-next-20220304 #1
>>>> [ 1.609169] Hardware name: Supermicro SYS-5019S-ML/X11SSH-F, BIOS
>>>> 2.5 11/26/2020
>>>> [ 1.609169] Stopper: 0x0 <- 0x0
>>>> [ 1.609169] Call Trace:
>>>> [ 1.609169] <TASK>
>>>> [ 1.609169] dump_stack_lvl+0x49/0x5e
>>>> [ 1.609169] dump_stack+0x10/0x12
>>>> [ 1.609169] lockdep_rcu_suspicious+0xed/0xf8
>>>> [ 1.609169] put_prev_task_stop+0x1dc/0x240
>>>> [ 1.609169] __schedule+0x751/0xcb0
>>>> [ 1.609169] ? trace_preempt_off+0x29/0xc0
>>>> [ 1.609169] ? smpboot_thread_fn+0x33/0x290
>>>> [ 1.609169] schedule+0x58/0xc0
>>>> [ 1.609169] smpboot_thread_fn+0xec/0x290
>>>> [ 1.609169] ? sort_range+0x30/0x30
>>>> [ 1.609169] kthread+0x107/0x130
>>>> [ 1.609169] ? kthread_complete_and_exit+0x20/0x20
>>>> [ 1.609169] ret_from_fork+0x22/0x30
>>>> [ 1.609169] </TASK>
>>>> [ 1.610276] smp: Bringing up secondary CPUs ...
>>>> [ 1.611596] x86: Booting SMP configuration:
>>>> [ 1.612179] .... node #0, CPUs: #1 #2 #3
>>>> [ 1.614396] smp: Brought up 1 node, 4 CPUs
>>>>
>>>> Reported-by: Linux Kernel Functional Testing <lkft@linaro.org>
>>>>
>>>> --
>>>> Linaro LKFT
>>>> https://lkft.linaro.org
>>>>
>>>> [1] https://qa-reports.linaro.org/lkft/linux-next-master/build/next-20220304/testrun/8235955/suite/linux-log-parser/test/check-kernel-warning-4655400/log
^ permalink raw reply related [flat|nested] 8+ messages in thread
* Re: [External] Re: [next] WARNING: suspicious RCU usage : include/linux/cgroup.h:494 suspicious rcu_dereference_check() usage
2022-03-05 0:57 ` [External] " Chengming Zhou
@ 2022-03-05 1:47 ` Zhouyi Zhou
2022-03-07 5:54 ` Naresh Kamboju
1 sibling, 0 replies; 8+ messages in thread
From: Zhouyi Zhou @ 2022-03-05 1:47 UTC (permalink / raw)
To: Chengming Zhou
Cc: Paul E. McKenney, Naresh Kamboju, Linux-Next Mailing List,
open list, lkft-triage, rcu, Stephen Rothwell, Peter Zijlstra,
Ingo Molnar, Will Deacon
Hi Chengming
On Sat, Mar 5, 2022 at 8:57 AM Chengming Zhou
<zhouchengming@bytedance.com> wrote:
>
> On 2022/3/5 4:28 上午, Zhouyi Zhou wrote:
> > Hi Paul
> >
> > Yes, your suggestion works!
> > Thank you for your guidance, this is the first time I ever did a
> > bisection, I gained greatly during this process!
>
> Hi Zhouyi, thanks for the bisection test.
You are very welcome ;-)
> Could this patch solve RCU warning? I just tested on my machine and there
> is no RCU warning any more.
Yes! your patch solve RCU warnings!
>
> diff --git a/include/linux/cgroup.h b/include/linux/cgroup.h
> index 1e356c222756..0d1ada8968d7 100644
> --- a/include/linux/cgroup.h
> +++ b/include/linux/cgroup.h
> @@ -450,6 +450,7 @@ extern struct mutex cgroup_mutex;
> extern spinlock_t css_set_lock;
> #define task_css_set_check(task, __c) \
> rcu_dereference_check((task)->cgroups, \
> + rcu_read_lock_sched_held() || \
> lockdep_is_held(&cgroup_mutex) || \
> lockdep_is_held(&css_set_lock) || \
> ((task)->flags & PF_EXITING) || (__c))
>
before apply your patch, there are RCU warnings in most recent linux-next:
http://154.223.142.244/logs/20220305/log.6d284ba80c0c485bcaa7bdf67f232d572640edc4.txt
afte apply your patch, there are no RCU warnings:
http://154.223.142.244/logs/20220305/log.chengmin.txt
Tested-by: Zhouyi Zhou <zhouzhouyi@gmail.com>
Thanks
Zhouyi
> Thanks.
>
> >
> > On Sat, Mar 5, 2022 at 3:44 AM Paul E. McKenney <paulmck@kernel.org> wrote:
> >>
> >> On Sat, Mar 05, 2022 at 03:38:33AM +0800, Zhouyi Zhou wrote:
> >>> Hi,
> >>> I can reproduce these warnings on my X86 VM.
> >>> Following the my backtrace:
> >>>
> >>> (gdb) bt
> >>> #0 lockdep_rcu_suspicious (file=file@entry=0xffffffff825ea8ff
> >>> "include/linux/cgroup.h", line=line@entry=494,
> >>> s=s@entry=0xffffffff825c5c50 "suspicious rcu_dereference_check()
> >>> usage") at ./arch/x86/include/asm/current.h:15
> >>> #1 0xffffffff81183103 in task_css (subsys_id=2,
> >>> task=0xffff888100804080) at ./include/linux/cgroup.h:494
> >>> #2 task_ca (tsk=0xffff888100804080) at kernel/sched/cpuacct.c:40
> >>> #3 cpuacct_charge (tsk=tsk@entry=0xffff888100804080,
> >>> cputime=cputime@entry=3344803) at kernel/sched/cpuacct.c:342
> >>> #4 0xffffffff81162655 in cgroup_account_cputime (delta_exec=3344803,
> >>> task=0xffff888100804080) at ./include/linux/cgroup.h:792
> >>> #5 update_curr (cfs_rq=cfs_rq@entry=0xffff88813b63f500) at
> >>> kernel/sched/fair.c:907
> >>> #6 0xffffffff81164797 in dequeue_entity (flags=10,
> >>> se=0xffff888100804100, cfs_rq=0xffff88813b63f500) at
> >>> kernel/sched/fair.c:5771
> >>> #7 dequeue_task_fair (rq=0xffff88813b63f440, p=0xffff888100804080,
> >>> flags=10) at kernel/sched/fair.c:5771
> >>> #8 0xffffffff8115412a in dequeue_task (flags=10,
> >>> p=0xffff888100804080, rq=0xffff88813b63f440) at
> >>> kernel/sched/core.c:2019
> >>> #9 __do_set_cpus_allowed (p=0xffff888100804080,
> >>> new_mask=0xffffffff831b4d40 <housekeeping+512>, flags=0) at
> >>> kernel/sched/core.c:2508
> >>> #10 0xffffffff811564ca in __set_cpus_allowed_ptr_locked
> >>> (p=p@entry=0xffff888100804080,
> >>> new_mask=new_mask@entry=0xffffffff831b4d40 <housekeeping+512>,
> >>> flags=flags@entry=0, rq=0xffff88813b63f440,
> >>> rf=rf@entry=0xffffc9000012bee8) at kernel/sched/core.c:2841
> >>> #11 0xffffffff81156573 in __set_cpus_allowed_ptr
> >>> (p=p@entry=0xffff888100804080, new_mask=0xffffffff831b4d40
> >>> <housekeeping+512>, flags=flags@entry=0)
> >>> at kernel/sched/core.c:2874
> >>> #12 0xffffffff8115664c in set_cpus_allowed_ptr
> >>> (p=p@entry=0xffff888100804080, new_mask=<optimized out>) at
> >>> kernel/sched/core.c:2879
> >>> #13 0xffffffff81144676 in kthreadd (unused=<optimized out>) at
> >>> kernel/kthread.c:724
> >>> #14 0xffffffff810019df in ret_from_fork () at arch/x86/entry/entry_64.S:295
> >>> #15 0x0000000000000000 in ?? ()
> >>>
> >>> Do the warnings have something to do with commit
> >>> dc6e0818bc9a0336d9accf3ea35d146d72aa7a18 (sched/cpuacct: Optimize away
> >>> RCU read lock) ?
> >>
> >> If you have not already done so, could you please try running on this
> >> commit and then on the commit immediately preceding it? Just as a
> >> authoritative way to answer your question. ;-)
> >>
> >> Thanx, Paul
> >>
> > git reset --hard dc6e0818bc9a0336d9accf3ea35d146d72aa7a18
> > make -j 16 bindeb-pkg
> > there are RCU WARNINGs:
> > http://154.223.142.244/logs/20220305/log.dc6e0818bc9a0336d9accf3ea35d146d72aa7a18.txt
> >
> > then I running on the commit immediately preceding it
> > git reset --hard 248cc9993d1cc12b8e9ed716cc3fc09f6c3517dd
> > make -j 16 bindeb-pkg
> > the WARNINGs are gone with the wind ;-)
> > http://154.223.142.244/logs/20220305/log.248cc9993d1cc12b8e9ed716cc3fc09f6c3517dd.txt
> >
> > Many thanks
> > Zhouyi
> >>> Many thanks
> >>> Zhouyi
> >>>
> >>> On Fri, Mar 4, 2022 at 10:43 PM Naresh Kamboju
> >>> <naresh.kamboju@linaro.org> wrote:
> >>>>
> >>>> While booting x86_64 with linux next-20220304 kernel the following kernel
> >>>> warning reported [1].
> >>>>
> >>>> metadata:
> >>>> git_ref: master
> >>>> git_repo: https://gitlab.com/Linaro/lkft/mirrors/next/linux-next
> >>>> git_sha: 6d284ba80c0c485bcaa7bdf67f232d572640edc4
> >>>> git_describe: next-20220304
> >>>> kernel-config: https://builds.tuxbuild.com/25uuYdm2vTO275aZ3IewZY5sKbU/config
> >>>>
> >>>>
> >>>> warning log:
> >>>> ---------
> >>>> [ 1.482171] MDS: Mitigation: Clear CPU buffers
> >>>> [ 1.485680] Freeing SMP alternatives memory: 52K
> >>>> [ 1.487341]
> >>>> [ 1.488169] =============================
> >>>> [ 1.488169] WARNING: suspicious RCU usage
> >>>> [ 1.488169] 5.17.0-rc6-next-20220304 #1 Not tainted
> >>>> [ 1.488169] -----------------------------
> >>>> [ 1.488169] include/linux/cgroup.h:494 suspicious
> >>>> rcu_dereference_check() usage!
> >>>> [ 1.488169]
> >>>> [ 1.488169] other info that might help us debug this:
> >>>> [ 1.488169]
> >>>> [ 1.488169]
> >>>> [ 1.488169] rcu_scheduler_active = 1, debug_locks = 1
> >>>> [ 1.488169] 2 locks held by kthreadd/2:
> >>>> [ 1.488169] #0: ffff9ba440352330 (&p->pi_lock){....}-{2:2}, at:
> >>>> task_rq_lock+0x2e/0x130
> >>>> [ 1.488169] #1: ffff9ba7a7a2d058 (&rq->__lock){-...}-{2:2}, at:
> >>>> task_rq_lock+0x5d/0x130
> >>>> [ 1.488169]
> >>>> [ 1.488169] stack backtrace:
> >>>> [ 1.488169] CPU: 0 PID: 2 Comm: kthreadd Not tainted
> >>>> 5.17.0-rc6-next-20220304 #1
> >>>> [ 1.488169] Hardware name: Supermicro SYS-5019S-ML/X11SSH-F, BIOS
> >>>> 2.5 11/26/2020
> >>>> [ 1.488169] Call Trace:
> >>>> [ 1.488169] <TASK>
> >>>> [ 1.488169] dump_stack_lvl+0x49/0x5e
> >>>> [ 1.488169] dump_stack+0x10/0x12
> >>>> [ 1.488169] lockdep_rcu_suspicious+0xed/0xf8
> >>>> [ 1.488169] cpuacct_charge+0x10c/0x120
> >>>> [ 1.488169] update_curr+0x165/0x340
> >>>> [ 1.488169] dequeue_entity+0x23/0x430
> >>>> [ 1.488169] dequeue_task_fair+0xba/0x3b0
> >>>> [ 1.488169] __do_set_cpus_allowed+0xca/0x2c0
> >>>> [ 1.488169] __set_cpus_allowed_ptr_locked+0x128/0x1b0
> >>>> [ 1.488169] set_cpus_allowed_ptr+0x43/0x70
> >>>> [ 1.488169] kthreadd+0x49/0x230
> >>>> [ 1.488169] ? kthread_is_per_cpu+0x30/0x30
> >>>> [ 1.488169] ret_from_fork+0x22/0x30
> >>>> [ 1.488169] </TASK>
> >>>> [ 1.488169]
> >>>> [ 1.488169] =============================
> >>>> [ 1.488169] WARNING: suspicious RCU usage
> >>>> [ 1.488169] 5.17.0-rc6-next-20220304 #1 Not tainted
> >>>> [ 1.488169] -----------------------------
> >>>> [ 1.488169] include/linux/cgroup.h:481 suspicious
> >>>> rcu_dereference_check() usage!
> >>>> [ 1.488169]
> >>>> [ 1.488169] other info that might help us debug this:
> >>>> [ 1.488169]
> >>>> [ 1.488169]
> >>>> [ 1.488169] rcu_scheduler_active = 1, debug_locks = 1
> >>>> [ 1.488169] 2 locks held by kthreadd/2:
> >>>> [ 1.488169] #0: ffff9ba440352330 (&p->pi_lock){....}-{2:2}, at:
> >>>> task_rq_lock+0x2e/0x130
> >>>> [ 1.488169] #1: ffff9ba7a7a2d058 (&rq->__lock){-...}-{2:2}, at:
> >>>> task_rq_lock+0x5d/0x130
> >>>> [ 1.488169]
> >>>> [ 1.488169] stack backtrace:
> >>>> [ 1.488169] CPU: 0 PID: 2 Comm: kthreadd Not tainted
> >>>> 5.17.0-rc6-next-20220304 #1
> >>>> [ 1.488169] Hardware name: Supermicro SYS-5019S-ML/X11SSH-F, BIOS
> >>>> 2.5 11/26/2020
> >>>> [ 1.488169] Call Trace:
> >>>> [ 1.488169] <TASK>
> >>>> [ 1.488169] dump_stack_lvl+0x49/0x5e
> >>>> [ 1.488169] dump_stack+0x10/0x12
> >>>> [ 1.488169] lockdep_rcu_suspicious+0xed/0xf8
> >>>> [ 1.488169] update_curr+0x2b7/0x340
> >>>> [ 1.488169] dequeue_entity+0x23/0x430
> >>>> [ 1.488169] dequeue_task_fair+0xba/0x3b0
> >>>> [ 1.488169] __do_set_cpus_allowed+0xca/0x2c0
> >>>> [ 1.488169] __set_cpus_allowed_ptr_locked+0x128/0x1b0
> >>>> [ 1.488169] set_cpus_allowed_ptr+0x43/0x70
> >>>> [ 1.488169] kthreadd+0x49/0x230
> >>>> [ 1.488169] ? kthread_is_per_cpu+0x30/0x30
> >>>> [ 1.488169] ret_from_fork+0x22/0x30
> >>>> [ 1.488169] </TASK>
> >>>> [ 1.488169]
> >>>> [ 1.488169] =============================
> >>>> [ 1.488169] WARNING: suspicious RCU usage
> >>>> [ 1.488169] 5.17.0-rc6-next-20220304 #1 Not tainted
> >>>> [ 1.488169] -----------------------------
> >>>> [ 1.488169] include/linux/cgroup.h:481 suspicious
> >>>> rcu_dereference_check() usage!
> >>>> [ 1.488169]
> >>>> [ 1.488169] other info that might help us debug this:
> >>>> [ 1.488169]
> >>>> [ 1.488169]
> >>>> [ 1.488169] rcu_scheduler_active = 1, debug_locks = 1
> >>>> [ 1.488169] no locks held by kthreadd/2.
> >>>> [ 1.488169]
> >>>> [ 1.488169] stack backtrace:
> >>>> [ 1.488169] CPU: 0 PID: 2 Comm: kthreadd Not tainted
> >>>> 5.17.0-rc6-next-20220304 #1
> >>>> [ 1.488169] Hardware name: Supermicro SYS-5019S-ML/X11SSH-F, BIOS
> >>>> 2.5 11/26/2020
> >>>> [ 1.488169] Call Trace:
> >>>> [ 1.488169] <IRQ>
> >>>> [ 1.488169] dump_stack_lvl+0x49/0x5e
> >>>> [ 1.488169] dump_stack+0x10/0x12
> >>>> [ 1.488169] lockdep_rcu_suspicious+0xed/0xf8
> >>>> [ 1.488169] account_system_index_time+0x127/0x130
> >>>> [ 1.488169] account_system_time+0x50/0x60
> >>>> [ 1.488169] account_process_tick+0x59/0x80
> >>>> [ 1.488169] update_process_times+0x58/0xe0
> >>>> [ 1.488169] tick_periodic+0x37/0xf0
> >>>> [ 1.488169] tick_handle_periodic+0x24/0x70
> >>>> [ 1.488169] timer_interrupt+0x18/0x20
> >>>> [ 1.488169] __handle_irq_event_percpu+0x95/0x2f0
> >>>> [ 1.488169] handle_irq_event+0x39/0x80
> >>>> [ 1.488169] handle_edge_irq+0xa4/0x240
> >>>> [ 1.488169] __common_interrupt+0x8d/0x170
> >>>> [ 1.488169] common_interrupt+0xbd/0xe0
> >>>> [ 1.488169] </IRQ>
> >>>> [ 1.488169] <TASK>
> >>>> [ 1.488169] asm_common_interrupt+0x1e/0x40
> >>>> [ 1.488169] RIP: 0010:_raw_spin_unlock_irqrestore+0x37/0x60
> >>>> [ 1.488169] Code: fc 48 83 c7 18 53 48 89 f3 48 8b 75 08 e8 21 83
> >>>> ed fe 4c 89 e7 e8 19 b0 ed fe 80 e7 02 74 06 e8 6f 77 fa fe fb bf 01
> >>>> 00 00 00 <e8> 24 6b e9 fe 65 8b 05 bd e1 28 66 85 c0 74 05 5b 41 5c 5d
> >>>> c3 0f
> >>>> [ 1.488169] RSP: 0000:ffffb75b0002fd50 EFLAGS: 00000202
> >>>> [ 1.488169] RAX: 0000000000000007 RBX: 0000000000000246 RCX: 0000000000000000
> >>>> [ 1.488169] RDX: 0000000000000000 RSI: ffffffff9a800a7c RDI: 0000000000000001
> >>>> [ 1.488169] RBP: ffffb75b0002fd60 R08: 0000000000000001 R09: 0000000000000001
> >>>> [ 1.488169] R10: 0000000000000002 R11: 0000000000000001 R12: ffff9ba440352318
> >>>> [ 1.488169] R13: 0000000000000000 R14: 0000000000000000 R15: ffff9ba7a7a2d040
> >>>> [ 1.488169] affine_move_task+0x2d4/0x5d0
> >>>> [ 1.488169] ? __this_cpu_preempt_check+0x13/0x20
> >>>> [ 1.488169] ? lock_is_held_type+0xdd/0x130
> >>>> [ 1.488169] ? enqueue_entity+0x1b8/0x520
> >>>> [ 1.488169] __set_cpus_allowed_ptr_locked+0x15c/0x1b0
> >>>> [ 1.488169] set_cpus_allowed_ptr+0x43/0x70
> >>>> [ 1.488169] kthreadd+0x49/0x230
> >>>> [ 1.488169] ? kthread_is_per_cpu+0x30/0x30
> >>>> [ 1.488169] ret_from_fork+0x22/0x30
> >>>> [ 1.488169] </TASK>
> >>>> [ 1.489211] smpboot: Estimated ratio of average max frequency by
> >>>> base frequency (times 1024): 1126
> >>>> [ 1.490189] smpboot: CPU0: Intel(R) Xeon(R) CPU E3-1220 v6 @
> >>>> 3.00GHz (family: 0x6, model: 0x9e, stepping: 0x9)
> >>>> [ 1.491635] cblist_init_generic: Setting adjustable number of
> >>>> callback queues.
> >>>> [ 1.492171] cblist_init_generic: Setting shift to 2 and lim to 1.
> >>>> [ 1.493226] cblist_init_generic: Setting shift to 2 and lim to 1.
> >>>> [ 1.494226] cblist_init_generic: Setting shift to 2 and lim to 1.
> >>>> [ 1.495219] Running RCU-tasks wait API self tests
> >>>> [ 1.598317] Performance Events: PEBS fmt3+, Skylake events, 32-deep
> >>>> LBR, full-width counters, Intel PMU driver.
> >>>> [ 1.599176] ... version: 4
> >>>> [ 1.600171] ... bit width: 48
> >>>> [ 1.601171] ... generic registers: 8
> >>>> [ 1.602171] ... value mask: 0000ffffffffffff
> >>>> [ 1.603171] ... max period: 00007fffffffffff
> >>>> [ 1.604176] ... fixed-purpose events: 3
> >>>> [ 1.605171] ... event mask: 00000007000000ff
> >>>> [ 1.606188] Callback from call_rcu_tasks_trace() invoked.
> >>>> [ 1.607450] rcu: Hierarchical SRCU implementation.
> >>>> [ 1.608310]
> >>>> [ 1.609169] =============================
> >>>> [ 1.609169] WARNING: suspicious RCU usage
> >>>> [ 1.609169] 5.17.0-rc6-next-20220304 #1 Not tainted
> >>>> [ 1.609169] -----------------------------
> >>>> [ 1.609169] include/linux/cgroup.h:481 suspicious
> >>>> rcu_dereference_check() usage!
> >>>> [ 1.609169]
> >>>> [ 1.609169] other info that might help us debug this:
> >>>> [ 1.609169]
> >>>> [ 1.609169]
> >>>> [ 1.609169] rcu_scheduler_active = 1, debug_locks = 1
> >>>> [ 1.609169] 1 lock held by migration/0/17:
> >>>> [ 1.609169] #0: ffff9ba7a7a2d058 (&rq->__lock){-.-.}-{2:2}, at:
> >>>> __schedule+0x12d/0xcb0
> >>>> [ 1.609169]
> >>>> [ 1.609169] stack backtrace:
> >>>> [ 1.609169] CPU: 0 PID: 17 Comm: migration/0 Not tainted
> >>>> 5.17.0-rc6-next-20220304 #1
> >>>> [ 1.609169] Hardware name: Supermicro SYS-5019S-ML/X11SSH-F, BIOS
> >>>> 2.5 11/26/2020
> >>>> [ 1.609169] Stopper: 0x0 <- 0x0
> >>>> [ 1.609169] Call Trace:
> >>>> [ 1.609169] <TASK>
> >>>> [ 1.609169] dump_stack_lvl+0x49/0x5e
> >>>> [ 1.609169] dump_stack+0x10/0x12
> >>>> [ 1.609169] lockdep_rcu_suspicious+0xed/0xf8
> >>>> [ 1.609169] put_prev_task_stop+0x1dc/0x240
> >>>> [ 1.609169] __schedule+0x751/0xcb0
> >>>> [ 1.609169] ? trace_preempt_off+0x29/0xc0
> >>>> [ 1.609169] ? smpboot_thread_fn+0x33/0x290
> >>>> [ 1.609169] schedule+0x58/0xc0
> >>>> [ 1.609169] smpboot_thread_fn+0xec/0x290
> >>>> [ 1.609169] ? sort_range+0x30/0x30
> >>>> [ 1.609169] kthread+0x107/0x130
> >>>> [ 1.609169] ? kthread_complete_and_exit+0x20/0x20
> >>>> [ 1.609169] ret_from_fork+0x22/0x30
> >>>> [ 1.609169] </TASK>
> >>>> [ 1.610276] smp: Bringing up secondary CPUs ...
> >>>> [ 1.611596] x86: Booting SMP configuration:
> >>>> [ 1.612179] .... node #0, CPUs: #1 #2 #3
> >>>> [ 1.614396] smp: Brought up 1 node, 4 CPUs
> >>>>
> >>>> Reported-by: Linux Kernel Functional Testing <lkft@linaro.org>
> >>>>
> >>>> --
> >>>> Linaro LKFT
> >>>> https://lkft.linaro.org
> >>>>
> >>>> [1] https://qa-reports.linaro.org/lkft/linux-next-master/build/next-20220304/testrun/8235955/suite/linux-log-parser/test/check-kernel-warning-4655400/log
^ permalink raw reply [flat|nested] 8+ messages in thread
* Re: [External] Re: [next] WARNING: suspicious RCU usage : include/linux/cgroup.h:494 suspicious rcu_dereference_check() usage
2022-03-05 0:57 ` [External] " Chengming Zhou
2022-03-05 1:47 ` Zhouyi Zhou
@ 2022-03-07 5:54 ` Naresh Kamboju
1 sibling, 0 replies; 8+ messages in thread
From: Naresh Kamboju @ 2022-03-07 5:54 UTC (permalink / raw)
To: Chengming Zhou
Cc: Zhouyi Zhou, Paul E. McKenney, Linux-Next Mailing List,
open list, lkft-triage, rcu, Stephen Rothwell, Peter Zijlstra,
Ingo Molnar, Will Deacon
On Sat, 5 Mar 2022 at 06:27, Chengming Zhou <zhouchengming@bytedance.com> wrote:
>
> On 2022/3/5 4:28 上午, Zhouyi Zhou wrote:
> > Hi Paul
> >
> > Yes, your suggestion works!
> > Thank you for your guidance, this is the first time I ever did a
> > bisection, I gained greatly during this process!
>
> Hi Zhouyi, thanks for the bisection test.
> Could this patch solve RCU warning? I just tested on my machine and there
> is no RCU warning any more.
This patch solves the reported problem. The test link provided below [1].
Tested-by: Linux Kernel Functional Testing <lkft@linaro.org>
>
> diff --git a/include/linux/cgroup.h b/include/linux/cgroup.h
> index 1e356c222756..0d1ada8968d7 100644
> --- a/include/linux/cgroup.h
> +++ b/include/linux/cgroup.h
> @@ -450,6 +450,7 @@ extern struct mutex cgroup_mutex;
> extern spinlock_t css_set_lock;
> #define task_css_set_check(task, __c) \
> rcu_dereference_check((task)->cgroups, \
> + rcu_read_lock_sched_held() || \
> lockdep_is_held(&cgroup_mutex) || \
> lockdep_is_held(&css_set_lock) || \
> ((task)->flags & PF_EXITING) || (__c))
>
--
Linaro LKFT
https://lkft.linaro.org
[1] https://lkft.validation.linaro.org/scheduler/job/4664565#L339
^ permalink raw reply [flat|nested] 8+ messages in thread
end of thread, other threads:[~2022-03-07 5:54 UTC | newest]
Thread overview: 8+ messages (download: mbox.gz / follow: Atom feed)
-- links below jump to the message on this page --
2022-03-04 13:25 [next] WARNING: suspicious RCU usage : include/linux/cgroup.h:494 suspicious rcu_dereference_check() usage Naresh Kamboju
2022-03-04 19:38 ` Zhouyi Zhou
2022-03-04 19:44 ` Paul E. McKenney
2022-03-04 20:28 ` Zhouyi Zhou
2022-03-04 21:32 ` Paul E. McKenney
2022-03-05 0:57 ` [External] " Chengming Zhou
2022-03-05 1:47 ` Zhouyi Zhou
2022-03-07 5:54 ` Naresh Kamboju
This is a public inbox, see mirroring instructions
for how to clone and mirror all data and code used for this inbox;
as well as URLs for NNTP newsgroup(s).