| Message ID | 20220701024404.2228367-1-qiang1.zhang@intel.com (mailing list archive) |
|---|---|
| State | Accepted |
| Commit | 88cea4e18ed430aa1187063450236fc00408eaac |
| Headers | show |
| Series | [v2] rcu: Make tiny RCU support leak callbacks for debug-object errors | expand |
On Fri, Jul 01, 2022 at 10:44:04AM +0800, Zqiang wrote: > Currently, only tree RCU support leak callbacks setting when do > duplicate call_rcu(). this commit add leak callbacks setting when > fo duplicate call_rcu() for tiny RCU. > > Signed-off-by: Zqiang <qiang1.zhang@intel.com> This does look plausible, thank you! What testing have you done? One important test for Tiny RCU is that the size of the kernel not grow without a very good reason. In this case, the added code should be dead code in a production build (CONFIG_DEBUG_OBJECTS_RCU_HEAD=n), but it is good to check. It is of course also good to check that the messages print as expected, which is what rcutorture.object_debug is there to help with. Thanx, Paul > --- > v1->v2: > for do duplicate kvfree_call_rcu(), not set leak callbacks. > > kernel/rcu/tiny.c | 17 ++++++++++++++++- > 1 file changed, 16 insertions(+), 1 deletion(-) > > diff --git a/kernel/rcu/tiny.c b/kernel/rcu/tiny.c > index f0561ee16b9c..943d431b908f 100644 > --- a/kernel/rcu/tiny.c > +++ b/kernel/rcu/tiny.c > @@ -158,6 +158,10 @@ void synchronize_rcu(void) > } > EXPORT_SYMBOL_GPL(synchronize_rcu); > > +static void tiny_rcu_leak_callback(struct rcu_head *rhp) > +{ > +} > + > /* > * Post an RCU callback to be invoked after the end of an RCU grace > * period. But since we have but one CPU, that would be after any > @@ -165,9 +169,20 @@ EXPORT_SYMBOL_GPL(synchronize_rcu); > */ > void call_rcu(struct rcu_head *head, rcu_callback_t func) > { > + static atomic_t doublefrees; > unsigned long flags; > > - debug_rcu_head_queue(head); > + if (debug_rcu_head_queue(head)) { > + if (atomic_inc_return(&doublefrees) < 4) { > + pr_err("%s(): Double-freed CB %p->%pS()!!! ", __func__, head, head->func); > + mem_dump_obj(head); > + } > + > + if (!__is_kvfree_rcu_offset((unsigned long)head->func)) > + WRITE_ONCE(head->func, tiny_rcu_leak_callback); > + return; > + } > + > head->func = func; > head->next = NULL; > > -- > 2.25.1 >
On Fri, Jul 01, 2022 at 10:44:04AM +0800, Zqiang wrote: > Currently, only tree RCU support leak callbacks setting when do > duplicate call_rcu(). this commit add leak callbacks setting when > fo duplicate call_rcu() for tiny RCU. > > Signed-off-by: Zqiang <qiang1.zhang@intel.com> >This does look plausible, thank you! > >What testing have you done? > >One important test for Tiny RCU is that the size of the kernel not >grow without a very good reason. In this case, the added code should >be dead code in a production build (CONFIG_DEBUG_OBJECTS_RCU_HEAD=n), >but it is good to check. > >It is of course also good to check that the messages print as expected, >which is what rcutorture.object_debug is there to help with. In the condition that the CONFIG_DEBUG_OBJECTS_RCU_HEAD=n, the function directly returns zero. #else /* !CONFIG_DEBUG_OBJECTS_RCU_HEAD */ static inline int debug_rcu_head_queue(struct rcu_head *head) { return 0; } My test results are as follows: runqemu kvm slirp nographic qemuparams="-m 2048 -smp 1" bootparams="rcutorture.object_debug=1" -d log: root@qemux86-64:/# zcat /proc/config.gz | grep RCU # RCU Subsystem CONFIG_TINY_RCU=y CONFIG_DEBUG_OBJECTS_RCU_HEAD=y [ 1.015657] rcutorture: WARN: Duplicate call_rcu() test starting. [ 1.015659] ------------[ cut here ]------------ [ 1.015659] ODEBUG: activate active (active state 1) object type: rcu_head hint: 0x0 [ 1.015680] WARNING: CPU: 0 PID: 1 at lib/debugobjects.c:502 debug_print_object+0xda/0x100 [ 1.016329] Modules linked in: [ 1.016329] CPU: 0 PID: 1 Comm: swapper Not tainted 5.19.0-rc3-yoctodev-standard+ #214 [ 1.016329] Hardware name: QEMU Standard PC (Q35 + ICH9, 2009), BIOS rel-1.16.0-0-gd239552ce722-prebuilt.qemu.org 04/01/2014 [ 1.016329] RIP: 0010:debug_print_object+0xda/0x100 [ 1.016329] Code: 60 ec 45 92 e8 a7 7b a0 ff 4d 89 f9 4d 89 e8 44 89 e1 48 8b 14 dd 60 ec 45 92 4c 89 f6 48 c7 c7 e0 e1 45 92 e8 f9 d1 b3 00 90 <0f> e [ 1.016329] RSP: 0000:ffff888001337be0 EFLAGS: 00010086 [ 1.016329] RAX: 0000000000000000 RBX: 0000000000000003 RCX: 0000000000000000 [ 1.016329] RDX: 00000000ffffffd8 RSI: 0000000000000004 RDI: ffffed1000266f6e [ 1.016329] RBP: ffff888001337c10 R08: ffffffff90a56ee6 R09: fffffbfff25df5c2 [ 1.016329] R10: ffffffff92efae0b R11: fffffbfff25df5c1 R12: 0000000000000001 [ 1.016329] R13: ffffffff9227f520 R14: ffffffff9245e8a0 R15: 0000000000000000 [ 1.016329] FS: 0000000000000000(0000) GS:ffffffff92cbb000(0000) knlGS:0000000000000000 [ 1.016329] CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033 [ 1.016329] CR2: ffff888017401000 CR3: 0000000015a3c000 CR4: 00000000001506f0 [ 1.016329] Call Trace: [ 1.016329] <TASK> [ 1.016329] debug_object_activate+0x2b9/0x300 [ 1.016329] ? debug_object_assert_init+0x220/0x220 [ 1.016329] ? lockdep_hardirqs_on_prepare+0x13/0x210 [ 1.016329] ? call_rcu+0xde/0x150 [ 1.016329] ? trace_hardirqs_on+0x54/0x120 [ 1.016329] ? rcu_torture_fwd_cb_hist.cold+0xe9/0xe9 [ 1.016329] call_rcu+0x20/0x150 [ 1.016329] rcu_torture_init+0x1687/0x1759 [ 1.016329] ? srcu_init+0xaa/0xaa [ 1.016329] ? irq_debugfs_copy_devname+0x70/0x70 [ 1.016329] ? rcu_torture_barrier1cb+0x40/0x40 [ 1.016329] ? rcu_torture_barrier1cb+0x40/0x40 [ 1.016329] ? irq_pm_init_ops+0x19/0x19 [ 1.016329] ? mutex_unlock+0x12/0x20 [ 1.016329] ? srcu_init+0xaa/0xaa [ 1.016329] do_one_initcall+0xc1/0x310 [ 1.016329] ? initcall_blacklisted+0x140/0x140 [ 1.016329] ? parameq+0x20/0x90 [ 1.016329] ? __kmalloc+0x238/0x5d0 [ 1.016329] ? rcu_read_lock_sched_held+0xe/0x50 [ 1.016329] kernel_init_freeable+0x20a/0x268 [ 1.016329] ? rest_init+0x160/0x160 [ 1.016329] kernel_init+0x1e/0x140 [ 1.016329] ret_from_fork+0x22/0x30 [ 1.016329] </TASK> [ 1.016329] irq event stamp: 152 [ 1.016329] hardirqs last enabled at (151): [<ffffffff91da7a4c>] _raw_spin_unlock_irqrestore+0x4c/0x60 [ 1.016329] hardirqs last disabled at (152): [<ffffffff91da7811>] _raw_spin_lock_irqsave+0x71/0x90 [ 1.016329] softirqs last enabled at (0): [<ffffffff908a230c>] copy_process+0xc8c/0x31b0 [ 1.016329] softirqs last disabled at (0): [<0000000000000000>] 0x0 [ 1.016329] ---[ end trace 0000000000000000 ]--- [ 1.016329] ------------[ cut here ]------------ [ 1.016329] ODEBUG: active_state active (active state 1) object type: rcu_head hint: 0x0 [ 1.016329] WARNING: CPU: 0 PID: 1 at lib/debugobjects.c:502 debug_print_object+0xda/0x100 [ 1.016329] Modules linked in: [ 1.016329] CPU: 0 PID: 1 Comm: swapper Tainted: G W 5.19.0-rc3-yoctodev-standard+ #214 [ 1.016329] Hardware name: QEMU Standard PC (Q35 + ICH9, 2009), BIOS rel-1.16.0-0-gd239552ce722-prebuilt.qemu.org 04/01/2014 [ 1.016329] RIP: 0010:debug_print_object+0xda/0x100 [ 1.016329] Code: 60 ec 45 92 e8 a7 7b a0 ff 4d 89 f9 4d 89 e8 44 89 e1 48 8b 14 dd 60 ec 45 92 4c 89 f6 48 c7 c7 e0 e1 45 92 e8 f9 d1 b3 00 90 <0f> e [ 1.016329] RSP: 0000:ffff888001337bd0 EFLAGS: 00010082 [ 1.016329] RAX: 0000000000000000 RBX: 0000000000000003 RCX: 0000000000000000 [ 1.016329] RDX: 00000000ffffffd8 RSI: 0000000000000004 RDI: ffffed1000266f6c [ 1.016329] RBP: ffff888001337c00 R08: ffffffff90a56ee6 R09: fffffbfff25df5c2 [ 1.016329] R10: ffffffff92efae0b R11: fffffbfff25df5c1 R12: 0000000000000001 [ 1.016329] R13: ffffffff9227f520 R14: ffffffff9245e640 R15: 0000000000000000 [ 1.016329] FS: 0000000000000000(0000) GS:ffffffff92cbb000(0000) knlGS:0000000000000000 [ 1.016329] CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033 [ 1.016329] CR2: ffff888017401000 CR3: 0000000015a3c000 CR4: 00000000001506f0 [ 1.016329] Call Trace: [ 1.016329] <TASK> [ 1.016329] debug_object_active_state+0x1d7/0x210 [ 1.016329] ? debug_object_deactivate+0x210/0x210 [ 1.016329] ? lockdep_hardirqs_on_prepare+0x13/0x210 [ 1.016329] ? call_rcu+0xde/0x150 [ 1.016329] ? trace_hardirqs_on+0x54/0x120 [ 1.016329] ? rcu_torture_fwd_cb_hist.cold+0xe9/0xe9 [ 1.016329] call_rcu+0x39/0x150 [ 1.016329] rcu_torture_init+0x1687/0x1759 [ 1.016329] ? srcu_init+0xaa/0xaa [ 1.016329] ? irq_debugfs_copy_devname+0x70/0x70 [ 1.016329] ? rcu_torture_barrier1cb+0x40/0x40 [ 1.016329] ? rcu_torture_barrier1cb+0x40/0x40 [ 1.016329] ? irq_pm_init_ops+0x19/0x19 [ 1.016329] ? mutex_unlock+0x12/0x20 [ 1.016329] ? srcu_init+0xaa/0xaa [ 1.016329] do_one_initcall+0xc1/0x310 [ 1.016329] ? initcall_blacklisted+0x140/0x140 [ 1.016329] ? parameq+0x20/0x90 [ 1.016329] ? __kmalloc+0x238/0x5d0 [ 1.016329] ? rcu_read_lock_sched_held+0xe/0x50 [ 1.016329] kernel_init_freeable+0x20a/0x268 [ 1.016329] ? rest_init+0x160/0x160 [ 1.016329] kernel_init+0x1e/0x140 [ 1.016329] ret_from_fork+0x22/0x30 [ 1.016329] </TASK> [ 1.016329] irq event stamp: 152 [ 1.016329] hardirqs last enabled at (151): [<ffffffff91da7a4c>] _raw_spin_unlock_irqrestore+0x4c/0x60 [ 1.016329] hardirqs last disabled at (152): [<ffffffff91da7811>] _raw_spin_lock_irqsave+0x71/0x90 [ 1.016329] softirqs last enabled at (0): [<ffffffff908a230c>] copy_process+0xc8c/0x31b0 [ 1.016329] softirqs last disabled at (0): [<0000000000000000>] 0x0 [ 1.016329] ---[ end trace 0000000000000000 ]--- [ 1.016329] call_rcu(): Double-freed CB (____ptrval____)->rcu_torture_leak_cb+0x0/0x10()!!! non-slab/vmalloc memory [ 1.016329] ------------[ cut here ]------------ [ 1.016329] ODEBUG: activate active (active state 1) object type: rcu_head hint: 0x0 [ 1.016329] WARNING: CPU: 0 PID: 1 at lib/debugobjects.c:502 debug_print_object+0xda/0x100 [ 1.016329] Modules linked in: [ 1.016329] CPU: 0 PID: 1 Comm: swapper Tainted: G W 5.19.0-rc3-yoctodev-standard+ #214 [ 1.016329] Hardware name: QEMU Standard PC (Q35 + ICH9, 2009), BIOS rel-1.16.0-0-gd239552ce722-prebuilt.qemu.org 04/01/2014 [ 1.016329] RIP: 0010:debug_print_object+0xda/0x100 [ 1.016329] Code: 60 ec 45 92 e8 a7 7b a0 ff 4d 89 f9 4d 89 e8 44 89 e1 48 8b 14 dd 60 ec 45 92 4c 89 f6 48 c7 c7 e0 e1 45 92 e8 f9 d1 b3 00 90 <0f> e [ 1.016329] RSP: 0000:ffff888001337be0 EFLAGS: 00010086 [ 1.016329] RAX: 0000000000000000 RBX: 0000000000000003 RCX: 0000000000000000 [ 1.016329] RDX: 00000000ffffffd8 RSI: 0000000000000004 RDI: ffffed1000266f6e [ 1.016329] RBP: ffff888001337c10 R08: ffffffff90a56ee6 R09: fffffbfff25df5c2 [ 1.016329] R10: ffffffff92efae0b R11: fffffbfff25df5c1 R12: 0000000000000001 [ 1.016329] R13: ffffffff9227f520 R14: ffffffff9245e8a0 R15: 0000000000000000 [ 1.016329] FS: 0000000000000000(0000) GS:ffffffff92cbb000(0000) knlGS:0000000000000000 [ 1.016329] CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033 [ 1.016329] CR2: ffff888017401000 CR3: 0000000015a3c000 CR4: 00000000001506f0 [ 1.016329] Call Trace: [ 1.016329] <TASK> [ 1.016329] debug_object_activate+0x2b9/0x300 [ 1.016329] ? debug_object_assert_init+0x220/0x220 [ 1.016329] ? _raw_spin_unlock+0x23/0x30 [ 1.016329] ? find_vmap_area+0x5c/0x90 [ 1.016329] ? do_raw_spin_unlock+0x85/0xe0 [ 1.016329] ? rcu_torture_fwd_cb_hist.cold+0xe9/0xe9 [ 1.016329] call_rcu+0x20/0x150 [ 1.016329] rcu_torture_init+0x16aa/0x1759 [ 1.016329] ? srcu_init+0xaa/0xaa [ 1.016329] ? irq_debugfs_copy_devname+0x70/0x70 [ 1.016329] ? rcu_torture_barrier1cb+0x40/0x40 [ 1.016329] ? srcu_torture_completed+0x10/0x10 [ 1.016329] ? irq_pm_init_ops+0x19/0x19 [ 1.016329] ? mutex_unlock+0x12/0x20 [ 1.016329] ? srcu_init+0xaa/0xaa [ 1.016329] do_one_initcall+0xc1/0x310 [ 1.016329] ? initcall_blacklisted+0x140/0x140 [ 1.016329] ? parameq+0x20/0x90 [ 1.016329] ? __kmalloc+0x238/0x5d0 [ 1.016329] ? rcu_read_lock_sched_held+0xe/0x50 [ 1.016329] kernel_init_freeable+0x20a/0x268 [ 1.016329] ? rest_init+0x160/0x160 [ 1.016329] kernel_init+0x1e/0x140 [ 1.016329] ret_from_fork+0x22/0x30 [ 1.016329] </TASK> [ 1.016329] irq event stamp: 152 [ 1.016329] hardirqs last enabled at (151): [<ffffffff91da7a4c>] _raw_spin_unlock_irqrestore+0x4c/0x60 [ 1.016329] hardirqs last disabled at (152): [<ffffffff91da7811>] _raw_spin_lock_irqsave+0x71/0x90 [ 1.016329] softirqs last enabled at (0): [<ffffffff908a230c>] copy_process+0xc8c/0x31b0 [ 1.016329] softirqs last disabled at (0): [<0000000000000000>] 0x0 [ 1.016329] ---[ end trace 0000000000000000 ]--- [ 1.016329] ------------[ cut here ]------------ [ 1.016329] ODEBUG: active_state active (active state 1) object type: rcu_head hint: 0x0 [ 1.016329] WARNING: CPU: 0 PID: 1 at lib/debugobjects.c:502 debug_print_object+0xda/0x100 [ 1.016329] Modules linked in: [ 1.016329] CPU: 0 PID: 1 Comm: swapper Tainted: G W 5.19.0-rc3-yoctodev-standard+ #214 [ 1.016329] Hardware name: QEMU Standard PC (Q35 + ICH9, 2009), BIOS rel-1.16.0-0-gd239552ce722-prebuilt.qemu.org 04/01/2014 [ 1.016329] RIP: 0010:debug_print_object+0xda/0x100 [ 1.016329] Code: 60 ec 45 92 e8 a7 7b a0 ff 4d 89 f9 4d 89 e8 44 89 e1 48 8b 14 dd 60 ec 45 92 4c 89 f6 48 c7 c7 e0 e1 45 92 e8 f9 d1 b3 00 90 <0f> e [ 1.016329] RSP: 0000:ffff888001337bd0 EFLAGS: 00010082 [ 1.016329] RAX: 0000000000000000 RBX: 0000000000000003 RCX: 0000000000000000 [ 1.016329] RDX: 00000000ffffffd8 RSI: 0000000000000004 RDI: ffffed1000266f6c [ 1.016329] RBP: ffff888001337c00 R08: ffffffff90a56ee6 R09: fffffbfff25df5c2 [ 1.016329] R10: ffffffff92efae0b R11: fffffbfff25df5c1 R12: 0000000000000001 [ 1.016329] R13: ffffffff9227f520 R14: ffffffff9245e640 R15: 0000000000000000 [ 1.016329] FS: 0000000000000000(0000) GS:ffffffff92cbb000(0000) knlGS:0000000000000000 [ 1.016329] CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033 [ 1.016329] CR2: ffff888017401000 CR3: 0000000015a3c000 CR4: 00000000001506f0 [ 1.016329] Call Trace: [ 1.016329] <TASK> [ 1.016329] debug_object_active_state+0x1d7/0x210 [ 1.016329] ? debug_object_deactivate+0x210/0x210 [ 1.016329] ? _raw_spin_unlock+0x23/0x30 [ 1.016329] ? find_vmap_area+0x5c/0x90 [ 1.016329] ? do_raw_spin_unlock+0x85/0xe0 [ 1.016329] ? rcu_torture_fwd_cb_hist.cold+0xe9/0xe9 [ 1.016329] call_rcu+0x39/0x150 [ 1.016329] rcu_torture_init+0x16aa/0x1759 [ 1.016329] ? srcu_init+0xaa/0xaa [ 1.016329] ? irq_debugfs_copy_devname+0x70/0x70 [ 1.016329] ? rcu_torture_barrier1cb+0x40/0x40 [ 1.016329] ? srcu_torture_completed+0x10/0x10 [ 1.016329] ? irq_pm_init_ops+0x19/0x19 [ 1.016329] ? mutex_unlock+0x12/0x20 [ 1.016329] ? srcu_init+0xaa/0xaa [ 1.016329] do_one_initcall+0xc1/0x310 [ 1.016329] ? initcall_blacklisted+0x140/0x140 [ 1.016329] ? parameq+0x20/0x90 [ 1.016329] ? __kmalloc+0x238/0x5d0 [ 1.016329] ? rcu_read_lock_sched_held+0xe/0x50 [ 1.016329] kernel_init_freeable+0x20a/0x268 [ 1.016329] ? rest_init+0x160/0x160 [ 1.016329] kernel_init+0x1e/0x140 [ 1.016329] ret_from_fork+0x22/0x30 [ 1.016329] </TASK> [ 1.016329] irq event stamp: 152 [ 1.016329] hardirqs last enabled at (151): [<ffffffff91da7a4c>] _raw_spin_unlock_irqrestore+0x4c/0x60 [ 1.016329] hardirqs last disabled at (152): [<ffffffff91da7811>] _raw_spin_lock_irqsave+0x71/0x90 [ 1.016329] softirqs last enabled at (0): [<ffffffff908a230c>] copy_process+0xc8c/0x31b0 [ 1.016329] softirqs last disabled at (0): [<0000000000000000>] 0x0 [ 1.016329] ---[ end trace 0000000000000000 ]--- [ 1.016329] call_rcu(): Double-freed CB (____ptrval____)->rcu_torture_leak_cb+0x0/0x10()!!! slab kmalloc-16 start ffff888003f49240 pointer offset 06 [ 1.101401] rcu-torture: rcu_torture_read_exit: Start of test Thanks Zqiang > > Thanx, Paul > --- > v1->v2: > for do duplicate kvfree_call_rcu(), not set leak callbacks. > > kernel/rcu/tiny.c | 17 ++++++++++++++++- > 1 file changed, 16 insertions(+), 1 deletion(-) > > diff --git a/kernel/rcu/tiny.c b/kernel/rcu/tiny.c > index f0561ee16b9c..943d431b908f 100644 > --- a/kernel/rcu/tiny.c > +++ b/kernel/rcu/tiny.c > @@ -158,6 +158,10 @@ void synchronize_rcu(void) > } > EXPORT_SYMBOL_GPL(synchronize_rcu); > > +static void tiny_rcu_leak_callback(struct rcu_head *rhp) > +{ > +} > + > /* > * Post an RCU callback to be invoked after the end of an RCU grace > * period. But since we have but one CPU, that would be after any > @@ -165,9 +169,20 @@ EXPORT_SYMBOL_GPL(synchronize_rcu); > */ > void call_rcu(struct rcu_head *head, rcu_callback_t func) > { > + static atomic_t doublefrees; > unsigned long flags; > > - debug_rcu_head_queue(head); > + if (debug_rcu_head_queue(head)) { > + if (atomic_inc_return(&doublefrees) < 4) { > + pr_err("%s(): Double-freed CB %p->%pS()!!! ", __func__, head, head->func); > + mem_dump_obj(head); > + } > + > + if (!__is_kvfree_rcu_offset((unsigned long)head->func)) > + WRITE_ONCE(head->func, tiny_rcu_leak_callback); > + return; > + } > + > head->func = func; > head->next = NULL; > > -- > 2.25.1 >
On Wed, Jul 06, 2022 at 02:00:51AM +0000, Zhang, Qiang1 wrote: > On Fri, Jul 01, 2022 at 10:44:04AM +0800, Zqiang wrote: > > Currently, only tree RCU support leak callbacks setting when do > > duplicate call_rcu(). this commit add leak callbacks setting when > > fo duplicate call_rcu() for tiny RCU. > > > > Signed-off-by: Zqiang <qiang1.zhang@intel.com> > > >This does look plausible, thank you! > > > >What testing have you done? > > > >One important test for Tiny RCU is that the size of the kernel not > >grow without a very good reason. In this case, the added code should > >be dead code in a production build (CONFIG_DEBUG_OBJECTS_RCU_HEAD=n), > >but it is good to check. > > > >It is of course also good to check that the messages print as expected, > >which is what rcutorture.object_debug is there to help with. > > In the condition that the CONFIG_DEBUG_OBJECTS_RCU_HEAD=n, the function directly returns zero. > > #else /* !CONFIG_DEBUG_OBJECTS_RCU_HEAD */ > static inline int debug_rcu_head_queue(struct rcu_head *head) > { > return 0; > } Yes, like I said, the added code -should- be dead code. But there is often a gap between "should" and "is", for example, compilers don't always do what we would like them to. So please use the "size vmlinux" command with and without your patch for a kernel built (both times) with CONFIG_TINY_RCU=y and CONFIG_DEBUG_OBJECTS_RCU_HEAD==n. The rest of the test results look good, thank you! Thanx, Paul > My test results are as follows: > > runqemu kvm slirp nographic qemuparams="-m 2048 -smp 1" bootparams="rcutorture.object_debug=1" -d > > log: > root@qemux86-64:/# zcat /proc/config.gz | grep RCU > # RCU Subsystem > CONFIG_TINY_RCU=y > CONFIG_DEBUG_OBJECTS_RCU_HEAD=y > > [ 1.015657] rcutorture: WARN: Duplicate call_rcu() test starting. > [ 1.015659] ------------[ cut here ]------------ > [ 1.015659] ODEBUG: activate active (active state 1) object type: rcu_head hint: 0x0 > [ 1.015680] WARNING: CPU: 0 PID: 1 at lib/debugobjects.c:502 debug_print_object+0xda/0x100 > [ 1.016329] Modules linked in: > [ 1.016329] CPU: 0 PID: 1 Comm: swapper Not tainted 5.19.0-rc3-yoctodev-standard+ #214 > [ 1.016329] Hardware name: QEMU Standard PC (Q35 + ICH9, 2009), BIOS rel-1.16.0-0-gd239552ce722-prebuilt.qemu.org 04/01/2014 > [ 1.016329] RIP: 0010:debug_print_object+0xda/0x100 > [ 1.016329] Code: 60 ec 45 92 e8 a7 7b a0 ff 4d 89 f9 4d 89 e8 44 89 e1 48 8b 14 dd 60 ec 45 92 4c 89 f6 48 c7 c7 e0 e1 45 92 e8 f9 d1 b3 00 90 <0f> e > [ 1.016329] RSP: 0000:ffff888001337be0 EFLAGS: 00010086 > [ 1.016329] RAX: 0000000000000000 RBX: 0000000000000003 RCX: 0000000000000000 > [ 1.016329] RDX: 00000000ffffffd8 RSI: 0000000000000004 RDI: ffffed1000266f6e > [ 1.016329] RBP: ffff888001337c10 R08: ffffffff90a56ee6 R09: fffffbfff25df5c2 > [ 1.016329] R10: ffffffff92efae0b R11: fffffbfff25df5c1 R12: 0000000000000001 > [ 1.016329] R13: ffffffff9227f520 R14: ffffffff9245e8a0 R15: 0000000000000000 > [ 1.016329] FS: 0000000000000000(0000) GS:ffffffff92cbb000(0000) knlGS:0000000000000000 > [ 1.016329] CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033 > [ 1.016329] CR2: ffff888017401000 CR3: 0000000015a3c000 CR4: 00000000001506f0 > [ 1.016329] Call Trace: > [ 1.016329] <TASK> > [ 1.016329] debug_object_activate+0x2b9/0x300 > [ 1.016329] ? debug_object_assert_init+0x220/0x220 > [ 1.016329] ? lockdep_hardirqs_on_prepare+0x13/0x210 > [ 1.016329] ? call_rcu+0xde/0x150 > [ 1.016329] ? trace_hardirqs_on+0x54/0x120 > [ 1.016329] ? rcu_torture_fwd_cb_hist.cold+0xe9/0xe9 > [ 1.016329] call_rcu+0x20/0x150 > [ 1.016329] rcu_torture_init+0x1687/0x1759 > [ 1.016329] ? srcu_init+0xaa/0xaa > [ 1.016329] ? irq_debugfs_copy_devname+0x70/0x70 > [ 1.016329] ? rcu_torture_barrier1cb+0x40/0x40 > [ 1.016329] ? rcu_torture_barrier1cb+0x40/0x40 > [ 1.016329] ? irq_pm_init_ops+0x19/0x19 > [ 1.016329] ? mutex_unlock+0x12/0x20 > [ 1.016329] ? srcu_init+0xaa/0xaa > [ 1.016329] do_one_initcall+0xc1/0x310 > [ 1.016329] ? initcall_blacklisted+0x140/0x140 > [ 1.016329] ? parameq+0x20/0x90 > [ 1.016329] ? __kmalloc+0x238/0x5d0 > [ 1.016329] ? rcu_read_lock_sched_held+0xe/0x50 > [ 1.016329] kernel_init_freeable+0x20a/0x268 > [ 1.016329] ? rest_init+0x160/0x160 > [ 1.016329] kernel_init+0x1e/0x140 > [ 1.016329] ret_from_fork+0x22/0x30 > [ 1.016329] </TASK> > [ 1.016329] irq event stamp: 152 > [ 1.016329] hardirqs last enabled at (151): [<ffffffff91da7a4c>] _raw_spin_unlock_irqrestore+0x4c/0x60 > [ 1.016329] hardirqs last disabled at (152): [<ffffffff91da7811>] _raw_spin_lock_irqsave+0x71/0x90 > [ 1.016329] softirqs last enabled at (0): [<ffffffff908a230c>] copy_process+0xc8c/0x31b0 > [ 1.016329] softirqs last disabled at (0): [<0000000000000000>] 0x0 > [ 1.016329] ---[ end trace 0000000000000000 ]--- > [ 1.016329] ------------[ cut here ]------------ > [ 1.016329] ODEBUG: active_state active (active state 1) object type: rcu_head hint: 0x0 > [ 1.016329] WARNING: CPU: 0 PID: 1 at lib/debugobjects.c:502 debug_print_object+0xda/0x100 > [ 1.016329] Modules linked in: > [ 1.016329] CPU: 0 PID: 1 Comm: swapper Tainted: G W 5.19.0-rc3-yoctodev-standard+ #214 > [ 1.016329] Hardware name: QEMU Standard PC (Q35 + ICH9, 2009), BIOS rel-1.16.0-0-gd239552ce722-prebuilt.qemu.org 04/01/2014 > [ 1.016329] RIP: 0010:debug_print_object+0xda/0x100 > [ 1.016329] Code: 60 ec 45 92 e8 a7 7b a0 ff 4d 89 f9 4d 89 e8 44 89 e1 48 8b 14 dd 60 ec 45 92 4c 89 f6 48 c7 c7 e0 e1 45 92 e8 f9 d1 b3 00 90 <0f> e > [ 1.016329] RSP: 0000:ffff888001337bd0 EFLAGS: 00010082 > [ 1.016329] RAX: 0000000000000000 RBX: 0000000000000003 RCX: 0000000000000000 > [ 1.016329] RDX: 00000000ffffffd8 RSI: 0000000000000004 RDI: ffffed1000266f6c > [ 1.016329] RBP: ffff888001337c00 R08: ffffffff90a56ee6 R09: fffffbfff25df5c2 > [ 1.016329] R10: ffffffff92efae0b R11: fffffbfff25df5c1 R12: 0000000000000001 > [ 1.016329] R13: ffffffff9227f520 R14: ffffffff9245e640 R15: 0000000000000000 > [ 1.016329] FS: 0000000000000000(0000) GS:ffffffff92cbb000(0000) knlGS:0000000000000000 > [ 1.016329] CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033 > [ 1.016329] CR2: ffff888017401000 CR3: 0000000015a3c000 CR4: 00000000001506f0 > [ 1.016329] Call Trace: > [ 1.016329] <TASK> > [ 1.016329] debug_object_active_state+0x1d7/0x210 > [ 1.016329] ? debug_object_deactivate+0x210/0x210 > [ 1.016329] ? lockdep_hardirqs_on_prepare+0x13/0x210 > [ 1.016329] ? call_rcu+0xde/0x150 > [ 1.016329] ? trace_hardirqs_on+0x54/0x120 > [ 1.016329] ? rcu_torture_fwd_cb_hist.cold+0xe9/0xe9 > [ 1.016329] call_rcu+0x39/0x150 > [ 1.016329] rcu_torture_init+0x1687/0x1759 > [ 1.016329] ? srcu_init+0xaa/0xaa > [ 1.016329] ? irq_debugfs_copy_devname+0x70/0x70 > [ 1.016329] ? rcu_torture_barrier1cb+0x40/0x40 > [ 1.016329] ? rcu_torture_barrier1cb+0x40/0x40 > [ 1.016329] ? irq_pm_init_ops+0x19/0x19 > [ 1.016329] ? mutex_unlock+0x12/0x20 > [ 1.016329] ? srcu_init+0xaa/0xaa > [ 1.016329] do_one_initcall+0xc1/0x310 > [ 1.016329] ? initcall_blacklisted+0x140/0x140 > [ 1.016329] ? parameq+0x20/0x90 > [ 1.016329] ? __kmalloc+0x238/0x5d0 > [ 1.016329] ? rcu_read_lock_sched_held+0xe/0x50 > [ 1.016329] kernel_init_freeable+0x20a/0x268 > [ 1.016329] ? rest_init+0x160/0x160 > [ 1.016329] kernel_init+0x1e/0x140 > [ 1.016329] ret_from_fork+0x22/0x30 > [ 1.016329] </TASK> > [ 1.016329] irq event stamp: 152 > [ 1.016329] hardirqs last enabled at (151): [<ffffffff91da7a4c>] _raw_spin_unlock_irqrestore+0x4c/0x60 > [ 1.016329] hardirqs last disabled at (152): [<ffffffff91da7811>] _raw_spin_lock_irqsave+0x71/0x90 > [ 1.016329] softirqs last enabled at (0): [<ffffffff908a230c>] copy_process+0xc8c/0x31b0 > [ 1.016329] softirqs last disabled at (0): [<0000000000000000>] 0x0 > [ 1.016329] ---[ end trace 0000000000000000 ]--- > [ 1.016329] call_rcu(): Double-freed CB (____ptrval____)->rcu_torture_leak_cb+0x0/0x10()!!! non-slab/vmalloc memory > [ 1.016329] ------------[ cut here ]------------ > [ 1.016329] ODEBUG: activate active (active state 1) object type: rcu_head hint: 0x0 > [ 1.016329] WARNING: CPU: 0 PID: 1 at lib/debugobjects.c:502 debug_print_object+0xda/0x100 > [ 1.016329] Modules linked in: > [ 1.016329] CPU: 0 PID: 1 Comm: swapper Tainted: G W 5.19.0-rc3-yoctodev-standard+ #214 > [ 1.016329] Hardware name: QEMU Standard PC (Q35 + ICH9, 2009), BIOS rel-1.16.0-0-gd239552ce722-prebuilt.qemu.org 04/01/2014 > [ 1.016329] RIP: 0010:debug_print_object+0xda/0x100 > [ 1.016329] Code: 60 ec 45 92 e8 a7 7b a0 ff 4d 89 f9 4d 89 e8 44 89 e1 48 8b 14 dd 60 ec 45 92 4c 89 f6 48 c7 c7 e0 e1 45 92 e8 f9 d1 b3 00 90 <0f> e > [ 1.016329] RSP: 0000:ffff888001337be0 EFLAGS: 00010086 > [ 1.016329] RAX: 0000000000000000 RBX: 0000000000000003 RCX: 0000000000000000 > [ 1.016329] RDX: 00000000ffffffd8 RSI: 0000000000000004 RDI: ffffed1000266f6e > [ 1.016329] RBP: ffff888001337c10 R08: ffffffff90a56ee6 R09: fffffbfff25df5c2 > [ 1.016329] R10: ffffffff92efae0b R11: fffffbfff25df5c1 R12: 0000000000000001 > [ 1.016329] R13: ffffffff9227f520 R14: ffffffff9245e8a0 R15: 0000000000000000 > [ 1.016329] FS: 0000000000000000(0000) GS:ffffffff92cbb000(0000) knlGS:0000000000000000 > [ 1.016329] CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033 > [ 1.016329] CR2: ffff888017401000 CR3: 0000000015a3c000 CR4: 00000000001506f0 > [ 1.016329] Call Trace: > [ 1.016329] <TASK> > [ 1.016329] debug_object_activate+0x2b9/0x300 > [ 1.016329] ? debug_object_assert_init+0x220/0x220 > [ 1.016329] ? _raw_spin_unlock+0x23/0x30 > [ 1.016329] ? find_vmap_area+0x5c/0x90 > [ 1.016329] ? do_raw_spin_unlock+0x85/0xe0 > [ 1.016329] ? rcu_torture_fwd_cb_hist.cold+0xe9/0xe9 > [ 1.016329] call_rcu+0x20/0x150 > [ 1.016329] rcu_torture_init+0x16aa/0x1759 > [ 1.016329] ? srcu_init+0xaa/0xaa > [ 1.016329] ? irq_debugfs_copy_devname+0x70/0x70 > [ 1.016329] ? rcu_torture_barrier1cb+0x40/0x40 > [ 1.016329] ? srcu_torture_completed+0x10/0x10 > [ 1.016329] ? irq_pm_init_ops+0x19/0x19 > [ 1.016329] ? mutex_unlock+0x12/0x20 > [ 1.016329] ? srcu_init+0xaa/0xaa > [ 1.016329] do_one_initcall+0xc1/0x310 > [ 1.016329] ? initcall_blacklisted+0x140/0x140 > [ 1.016329] ? parameq+0x20/0x90 > [ 1.016329] ? __kmalloc+0x238/0x5d0 > [ 1.016329] ? rcu_read_lock_sched_held+0xe/0x50 > [ 1.016329] kernel_init_freeable+0x20a/0x268 > [ 1.016329] ? rest_init+0x160/0x160 > [ 1.016329] kernel_init+0x1e/0x140 > [ 1.016329] ret_from_fork+0x22/0x30 > [ 1.016329] </TASK> > [ 1.016329] irq event stamp: 152 > [ 1.016329] hardirqs last enabled at (151): [<ffffffff91da7a4c>] _raw_spin_unlock_irqrestore+0x4c/0x60 > [ 1.016329] hardirqs last disabled at (152): [<ffffffff91da7811>] _raw_spin_lock_irqsave+0x71/0x90 > [ 1.016329] softirqs last enabled at (0): [<ffffffff908a230c>] copy_process+0xc8c/0x31b0 > [ 1.016329] softirqs last disabled at (0): [<0000000000000000>] 0x0 > [ 1.016329] ---[ end trace 0000000000000000 ]--- > [ 1.016329] ------------[ cut here ]------------ > [ 1.016329] ODEBUG: active_state active (active state 1) object type: rcu_head hint: 0x0 > [ 1.016329] WARNING: CPU: 0 PID: 1 at lib/debugobjects.c:502 debug_print_object+0xda/0x100 > [ 1.016329] Modules linked in: > [ 1.016329] CPU: 0 PID: 1 Comm: swapper Tainted: G W 5.19.0-rc3-yoctodev-standard+ #214 > [ 1.016329] Hardware name: QEMU Standard PC (Q35 + ICH9, 2009), BIOS rel-1.16.0-0-gd239552ce722-prebuilt.qemu.org 04/01/2014 > [ 1.016329] RIP: 0010:debug_print_object+0xda/0x100 > [ 1.016329] Code: 60 ec 45 92 e8 a7 7b a0 ff 4d 89 f9 4d 89 e8 44 89 e1 48 8b 14 dd 60 ec 45 92 4c 89 f6 48 c7 c7 e0 e1 45 92 e8 f9 d1 b3 00 90 <0f> e > [ 1.016329] RSP: 0000:ffff888001337bd0 EFLAGS: 00010082 > [ 1.016329] RAX: 0000000000000000 RBX: 0000000000000003 RCX: 0000000000000000 > [ 1.016329] RDX: 00000000ffffffd8 RSI: 0000000000000004 RDI: ffffed1000266f6c > [ 1.016329] RBP: ffff888001337c00 R08: ffffffff90a56ee6 R09: fffffbfff25df5c2 > [ 1.016329] R10: ffffffff92efae0b R11: fffffbfff25df5c1 R12: 0000000000000001 > [ 1.016329] R13: ffffffff9227f520 R14: ffffffff9245e640 R15: 0000000000000000 > [ 1.016329] FS: 0000000000000000(0000) GS:ffffffff92cbb000(0000) knlGS:0000000000000000 > [ 1.016329] CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033 > [ 1.016329] CR2: ffff888017401000 CR3: 0000000015a3c000 CR4: 00000000001506f0 > [ 1.016329] Call Trace: > [ 1.016329] <TASK> > [ 1.016329] debug_object_active_state+0x1d7/0x210 > [ 1.016329] ? debug_object_deactivate+0x210/0x210 > [ 1.016329] ? _raw_spin_unlock+0x23/0x30 > [ 1.016329] ? find_vmap_area+0x5c/0x90 > [ 1.016329] ? do_raw_spin_unlock+0x85/0xe0 > [ 1.016329] ? rcu_torture_fwd_cb_hist.cold+0xe9/0xe9 > [ 1.016329] call_rcu+0x39/0x150 > [ 1.016329] rcu_torture_init+0x16aa/0x1759 > [ 1.016329] ? srcu_init+0xaa/0xaa > [ 1.016329] ? irq_debugfs_copy_devname+0x70/0x70 > [ 1.016329] ? rcu_torture_barrier1cb+0x40/0x40 > [ 1.016329] ? srcu_torture_completed+0x10/0x10 > [ 1.016329] ? irq_pm_init_ops+0x19/0x19 > [ 1.016329] ? mutex_unlock+0x12/0x20 > [ 1.016329] ? srcu_init+0xaa/0xaa > [ 1.016329] do_one_initcall+0xc1/0x310 > [ 1.016329] ? initcall_blacklisted+0x140/0x140 > [ 1.016329] ? parameq+0x20/0x90 > [ 1.016329] ? __kmalloc+0x238/0x5d0 > [ 1.016329] ? rcu_read_lock_sched_held+0xe/0x50 > [ 1.016329] kernel_init_freeable+0x20a/0x268 > [ 1.016329] ? rest_init+0x160/0x160 > [ 1.016329] kernel_init+0x1e/0x140 > [ 1.016329] ret_from_fork+0x22/0x30 > [ 1.016329] </TASK> > [ 1.016329] irq event stamp: 152 > [ 1.016329] hardirqs last enabled at (151): [<ffffffff91da7a4c>] _raw_spin_unlock_irqrestore+0x4c/0x60 > [ 1.016329] hardirqs last disabled at (152): [<ffffffff91da7811>] _raw_spin_lock_irqsave+0x71/0x90 > [ 1.016329] softirqs last enabled at (0): [<ffffffff908a230c>] copy_process+0xc8c/0x31b0 > [ 1.016329] softirqs last disabled at (0): [<0000000000000000>] 0x0 > [ 1.016329] ---[ end trace 0000000000000000 ]--- > [ 1.016329] call_rcu(): Double-freed CB (____ptrval____)->rcu_torture_leak_cb+0x0/0x10()!!! slab kmalloc-16 start ffff888003f49240 pointer offset 06 > [ 1.101401] rcu-torture: rcu_torture_read_exit: Start of test > > Thanks > Zqiang > > > > > > Thanx, Paul > > > --- > > v1->v2: > > for do duplicate kvfree_call_rcu(), not set leak callbacks. > > > > kernel/rcu/tiny.c | 17 ++++++++++++++++- > > 1 file changed, 16 insertions(+), 1 deletion(-) > > > > diff --git a/kernel/rcu/tiny.c b/kernel/rcu/tiny.c > > index f0561ee16b9c..943d431b908f 100644 > > --- a/kernel/rcu/tiny.c > > +++ b/kernel/rcu/tiny.c > > @@ -158,6 +158,10 @@ void synchronize_rcu(void) > > } > > EXPORT_SYMBOL_GPL(synchronize_rcu); > > > > +static void tiny_rcu_leak_callback(struct rcu_head *rhp) > > +{ > > +} > > + > > /* > > * Post an RCU callback to be invoked after the end of an RCU grace > > * period. But since we have but one CPU, that would be after any > > @@ -165,9 +169,20 @@ EXPORT_SYMBOL_GPL(synchronize_rcu); > > */ > > void call_rcu(struct rcu_head *head, rcu_callback_t func) > > { > > + static atomic_t doublefrees; > > unsigned long flags; > > > > - debug_rcu_head_queue(head); > > + if (debug_rcu_head_queue(head)) { > > + if (atomic_inc_return(&doublefrees) < 4) { > > + pr_err("%s(): Double-freed CB %p->%pS()!!! ", __func__, head, head->func); > > + mem_dump_obj(head); > > + } > > + > > + if (!__is_kvfree_rcu_offset((unsigned long)head->func)) > > + WRITE_ONCE(head->func, tiny_rcu_leak_callback); > > + return; > > + } > > + > > head->func = func; > > head->next = NULL; > > > > -- > > 2.25.1 > >
On Wed, Jul 06, 2022 at 02:00:51AM +0000, Zhang, Qiang1 wrote: > On Fri, Jul 01, 2022 at 10:44:04AM +0800, Zqiang wrote: > > Currently, only tree RCU support leak callbacks setting when do > > duplicate call_rcu(). this commit add leak callbacks setting when > > fo duplicate call_rcu() for tiny RCU. > > > > Signed-off-by: Zqiang <qiang1.zhang@intel.com> > > >This does look plausible, thank you! > > > >What testing have you done? > > > >One important test for Tiny RCU is that the size of the kernel not > >grow without a very good reason. In this case, the added code should > >be dead code in a production build (CONFIG_DEBUG_OBJECTS_RCU_HEAD=n), > >but it is good to check. > > > >It is of course also good to check that the messages print as expected, > >which is what rcutorture.object_debug is there to help with. > > In the condition that the CONFIG_DEBUG_OBJECTS_RCU_HEAD=n, the function directly returns zero. > > #else /* !CONFIG_DEBUG_OBJECTS_RCU_HEAD */ > static inline int debug_rcu_head_queue(struct rcu_head *head) > { > return 0; > } > >Yes, like I said, the added code -should- be dead code. But there is >often a gap between "should" and "is", for example, compilers don't >always do what we would like them to. So please use the "size vmlinux" >command with and without your patch for a kernel built (both times) >with CONFIG_TINY_RCU=y and CONFIG_DEBUG_OBJECTS_RCU_HEAD==n. > >The rest of the test results look good, thank you! Hi Paul Original: text data bss dec hex filename 26291319 20160143 15212544 61664006 3aceb06 vmlinux Applay patch: text data bss dec hex filename 26291319 20160431 15212544 61664294 3acec26 vmlinux Thanks Zqiang > > Thanx, Paul > > My test results are as follows: > > runqemu kvm slirp nographic qemuparams="-m 2048 -smp 1" bootparams="rcutorture.object_debug=1" -d > > log: > root@qemux86-64:/# zcat /proc/config.gz | grep RCU > # RCU Subsystem > CONFIG_TINY_RCU=y > CONFIG_DEBUG_OBJECTS_RCU_HEAD=y > > [ 1.015657] rcutorture: WARN: Duplicate call_rcu() test starting. > [ 1.015659] ------------[ cut here ]------------ > [ 1.015659] ODEBUG: activate active (active state 1) object type: rcu_head hint: 0x0 > [ 1.015680] WARNING: CPU: 0 PID: 1 at lib/debugobjects.c:502 debug_print_object+0xda/0x100 > [ 1.016329] Modules linked in: > [ 1.016329] CPU: 0 PID: 1 Comm: swapper Not tainted 5.19.0-rc3-yoctodev-standard+ #214 > [ 1.016329] Hardware name: QEMU Standard PC (Q35 + ICH9, 2009), BIOS rel-1.16.0-0-gd239552ce722-prebuilt.qemu.org 04/01/2014 > [ 1.016329] RIP: 0010:debug_print_object+0xda/0x100 > [ 1.016329] Code: 60 ec 45 92 e8 a7 7b a0 ff 4d 89 f9 4d 89 e8 44 89 e1 48 8b 14 dd 60 ec 45 92 4c 89 f6 48 c7 c7 e0 e1 45 92 e8 f9 d1 b3 00 90 <0f> e > [ 1.016329] RSP: 0000:ffff888001337be0 EFLAGS: 00010086 > [ 1.016329] RAX: 0000000000000000 RBX: 0000000000000003 RCX: 0000000000000000 > [ 1.016329] RDX: 00000000ffffffd8 RSI: 0000000000000004 RDI: ffffed1000266f6e > [ 1.016329] RBP: ffff888001337c10 R08: ffffffff90a56ee6 R09: fffffbfff25df5c2 > [ 1.016329] R10: ffffffff92efae0b R11: fffffbfff25df5c1 R12: 0000000000000001 > [ 1.016329] R13: ffffffff9227f520 R14: ffffffff9245e8a0 R15: 0000000000000000 > [ 1.016329] FS: 0000000000000000(0000) GS:ffffffff92cbb000(0000) knlGS:0000000000000000 > [ 1.016329] CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033 > [ 1.016329] CR2: ffff888017401000 CR3: 0000000015a3c000 CR4: 00000000001506f0 > [ 1.016329] Call Trace: > [ 1.016329] <TASK> > [ 1.016329] debug_object_activate+0x2b9/0x300 > [ 1.016329] ? debug_object_assert_init+0x220/0x220 > [ 1.016329] ? lockdep_hardirqs_on_prepare+0x13/0x210 > [ 1.016329] ? call_rcu+0xde/0x150 > [ 1.016329] ? trace_hardirqs_on+0x54/0x120 > [ 1.016329] ? rcu_torture_fwd_cb_hist.cold+0xe9/0xe9 > [ 1.016329] call_rcu+0x20/0x150 > [ 1.016329] rcu_torture_init+0x1687/0x1759 > [ 1.016329] ? srcu_init+0xaa/0xaa > [ 1.016329] ? irq_debugfs_copy_devname+0x70/0x70 > [ 1.016329] ? rcu_torture_barrier1cb+0x40/0x40 > [ 1.016329] ? rcu_torture_barrier1cb+0x40/0x40 > [ 1.016329] ? irq_pm_init_ops+0x19/0x19 > [ 1.016329] ? mutex_unlock+0x12/0x20 > [ 1.016329] ? srcu_init+0xaa/0xaa > [ 1.016329] do_one_initcall+0xc1/0x310 > [ 1.016329] ? initcall_blacklisted+0x140/0x140 > [ 1.016329] ? parameq+0x20/0x90 > [ 1.016329] ? __kmalloc+0x238/0x5d0 > [ 1.016329] ? rcu_read_lock_sched_held+0xe/0x50 > [ 1.016329] kernel_init_freeable+0x20a/0x268 > [ 1.016329] ? rest_init+0x160/0x160 > [ 1.016329] kernel_init+0x1e/0x140 > [ 1.016329] ret_from_fork+0x22/0x30 > [ 1.016329] </TASK> > [ 1.016329] irq event stamp: 152 > [ 1.016329] hardirqs last enabled at (151): [<ffffffff91da7a4c>] _raw_spin_unlock_irqrestore+0x4c/0x60 > [ 1.016329] hardirqs last disabled at (152): [<ffffffff91da7811>] _raw_spin_lock_irqsave+0x71/0x90 > [ 1.016329] softirqs last enabled at (0): [<ffffffff908a230c>] copy_process+0xc8c/0x31b0 > [ 1.016329] softirqs last disabled at (0): [<0000000000000000>] 0x0 > [ 1.016329] ---[ end trace 0000000000000000 ]--- > [ 1.016329] ------------[ cut here ]------------ > [ 1.016329] ODEBUG: active_state active (active state 1) object type: rcu_head hint: 0x0 > [ 1.016329] WARNING: CPU: 0 PID: 1 at lib/debugobjects.c:502 debug_print_object+0xda/0x100 > [ 1.016329] Modules linked in: > [ 1.016329] CPU: 0 PID: 1 Comm: swapper Tainted: G W 5.19.0-rc3-yoctodev-standard+ #214 > [ 1.016329] Hardware name: QEMU Standard PC (Q35 + ICH9, 2009), BIOS rel-1.16.0-0-gd239552ce722-prebuilt.qemu.org 04/01/2014 > [ 1.016329] RIP: 0010:debug_print_object+0xda/0x100 > [ 1.016329] Code: 60 ec 45 92 e8 a7 7b a0 ff 4d 89 f9 4d 89 e8 44 89 e1 48 8b 14 dd 60 ec 45 92 4c 89 f6 48 c7 c7 e0 e1 45 92 e8 f9 d1 b3 00 90 <0f> e > [ 1.016329] RSP: 0000:ffff888001337bd0 EFLAGS: 00010082 > [ 1.016329] RAX: 0000000000000000 RBX: 0000000000000003 RCX: 0000000000000000 > [ 1.016329] RDX: 00000000ffffffd8 RSI: 0000000000000004 RDI: ffffed1000266f6c > [ 1.016329] RBP: ffff888001337c00 R08: ffffffff90a56ee6 R09: fffffbfff25df5c2 > [ 1.016329] R10: ffffffff92efae0b R11: fffffbfff25df5c1 R12: 0000000000000001 > [ 1.016329] R13: ffffffff9227f520 R14: ffffffff9245e640 R15: 0000000000000000 > [ 1.016329] FS: 0000000000000000(0000) GS:ffffffff92cbb000(0000) knlGS:0000000000000000 > [ 1.016329] CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033 > [ 1.016329] CR2: ffff888017401000 CR3: 0000000015a3c000 CR4: 00000000001506f0 > [ 1.016329] Call Trace: > [ 1.016329] <TASK> > [ 1.016329] debug_object_active_state+0x1d7/0x210 > [ 1.016329] ? debug_object_deactivate+0x210/0x210 > [ 1.016329] ? lockdep_hardirqs_on_prepare+0x13/0x210 > [ 1.016329] ? call_rcu+0xde/0x150 > [ 1.016329] ? trace_hardirqs_on+0x54/0x120 > [ 1.016329] ? rcu_torture_fwd_cb_hist.cold+0xe9/0xe9 > [ 1.016329] call_rcu+0x39/0x150 > [ 1.016329] rcu_torture_init+0x1687/0x1759 > [ 1.016329] ? srcu_init+0xaa/0xaa > [ 1.016329] ? irq_debugfs_copy_devname+0x70/0x70 > [ 1.016329] ? rcu_torture_barrier1cb+0x40/0x40 > [ 1.016329] ? rcu_torture_barrier1cb+0x40/0x40 > [ 1.016329] ? irq_pm_init_ops+0x19/0x19 > [ 1.016329] ? mutex_unlock+0x12/0x20 > [ 1.016329] ? srcu_init+0xaa/0xaa > [ 1.016329] do_one_initcall+0xc1/0x310 > [ 1.016329] ? initcall_blacklisted+0x140/0x140 > [ 1.016329] ? parameq+0x20/0x90 > [ 1.016329] ? __kmalloc+0x238/0x5d0 > [ 1.016329] ? rcu_read_lock_sched_held+0xe/0x50 > [ 1.016329] kernel_init_freeable+0x20a/0x268 > [ 1.016329] ? rest_init+0x160/0x160 > [ 1.016329] kernel_init+0x1e/0x140 > [ 1.016329] ret_from_fork+0x22/0x30 > [ 1.016329] </TASK> > [ 1.016329] irq event stamp: 152 > [ 1.016329] hardirqs last enabled at (151): [<ffffffff91da7a4c>] _raw_spin_unlock_irqrestore+0x4c/0x60 > [ 1.016329] hardirqs last disabled at (152): [<ffffffff91da7811>] _raw_spin_lock_irqsave+0x71/0x90 > [ 1.016329] softirqs last enabled at (0): [<ffffffff908a230c>] copy_process+0xc8c/0x31b0 > [ 1.016329] softirqs last disabled at (0): [<0000000000000000>] 0x0 > [ 1.016329] ---[ end trace 0000000000000000 ]--- > [ 1.016329] call_rcu(): Double-freed CB (____ptrval____)->rcu_torture_leak_cb+0x0/0x10()!!! non-slab/vmalloc memory > [ 1.016329] ------------[ cut here ]------------ > [ 1.016329] ODEBUG: activate active (active state 1) object type: rcu_head hint: 0x0 > [ 1.016329] WARNING: CPU: 0 PID: 1 at lib/debugobjects.c:502 debug_print_object+0xda/0x100 > [ 1.016329] Modules linked in: > [ 1.016329] CPU: 0 PID: 1 Comm: swapper Tainted: G W 5.19.0-rc3-yoctodev-standard+ #214 > [ 1.016329] Hardware name: QEMU Standard PC (Q35 + ICH9, 2009), BIOS rel-1.16.0-0-gd239552ce722-prebuilt.qemu.org 04/01/2014 > [ 1.016329] RIP: 0010:debug_print_object+0xda/0x100 > [ 1.016329] Code: 60 ec 45 92 e8 a7 7b a0 ff 4d 89 f9 4d 89 e8 44 89 e1 48 8b 14 dd 60 ec 45 92 4c 89 f6 48 c7 c7 e0 e1 45 92 e8 f9 d1 b3 00 90 <0f> e > [ 1.016329] RSP: 0000:ffff888001337be0 EFLAGS: 00010086 > [ 1.016329] RAX: 0000000000000000 RBX: 0000000000000003 RCX: 0000000000000000 > [ 1.016329] RDX: 00000000ffffffd8 RSI: 0000000000000004 RDI: ffffed1000266f6e > [ 1.016329] RBP: ffff888001337c10 R08: ffffffff90a56ee6 R09: fffffbfff25df5c2 > [ 1.016329] R10: ffffffff92efae0b R11: fffffbfff25df5c1 R12: 0000000000000001 > [ 1.016329] R13: ffffffff9227f520 R14: ffffffff9245e8a0 R15: 0000000000000000 > [ 1.016329] FS: 0000000000000000(0000) GS:ffffffff92cbb000(0000) knlGS:0000000000000000 > [ 1.016329] CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033 > [ 1.016329] CR2: ffff888017401000 CR3: 0000000015a3c000 CR4: 00000000001506f0 > [ 1.016329] Call Trace: > [ 1.016329] <TASK> > [ 1.016329] debug_object_activate+0x2b9/0x300 > [ 1.016329] ? debug_object_assert_init+0x220/0x220 > [ 1.016329] ? _raw_spin_unlock+0x23/0x30 > [ 1.016329] ? find_vmap_area+0x5c/0x90 > [ 1.016329] ? do_raw_spin_unlock+0x85/0xe0 > [ 1.016329] ? rcu_torture_fwd_cb_hist.cold+0xe9/0xe9 > [ 1.016329] call_rcu+0x20/0x150 > [ 1.016329] rcu_torture_init+0x16aa/0x1759 > [ 1.016329] ? srcu_init+0xaa/0xaa > [ 1.016329] ? irq_debugfs_copy_devname+0x70/0x70 > [ 1.016329] ? rcu_torture_barrier1cb+0x40/0x40 > [ 1.016329] ? srcu_torture_completed+0x10/0x10 > [ 1.016329] ? irq_pm_init_ops+0x19/0x19 > [ 1.016329] ? mutex_unlock+0x12/0x20 > [ 1.016329] ? srcu_init+0xaa/0xaa > [ 1.016329] do_one_initcall+0xc1/0x310 > [ 1.016329] ? initcall_blacklisted+0x140/0x140 > [ 1.016329] ? parameq+0x20/0x90 > [ 1.016329] ? __kmalloc+0x238/0x5d0 > [ 1.016329] ? rcu_read_lock_sched_held+0xe/0x50 > [ 1.016329] kernel_init_freeable+0x20a/0x268 > [ 1.016329] ? rest_init+0x160/0x160 > [ 1.016329] kernel_init+0x1e/0x140 > [ 1.016329] ret_from_fork+0x22/0x30 > [ 1.016329] </TASK> > [ 1.016329] irq event stamp: 152 > [ 1.016329] hardirqs last enabled at (151): [<ffffffff91da7a4c>] _raw_spin_unlock_irqrestore+0x4c/0x60 > [ 1.016329] hardirqs last disabled at (152): [<ffffffff91da7811>] _raw_spin_lock_irqsave+0x71/0x90 > [ 1.016329] softirqs last enabled at (0): [<ffffffff908a230c>] copy_process+0xc8c/0x31b0 > [ 1.016329] softirqs last disabled at (0): [<0000000000000000>] 0x0 > [ 1.016329] ---[ end trace 0000000000000000 ]--- > [ 1.016329] ------------[ cut here ]------------ > [ 1.016329] ODEBUG: active_state active (active state 1) object type: rcu_head hint: 0x0 > [ 1.016329] WARNING: CPU: 0 PID: 1 at lib/debugobjects.c:502 debug_print_object+0xda/0x100 > [ 1.016329] Modules linked in: > [ 1.016329] CPU: 0 PID: 1 Comm: swapper Tainted: G W 5.19.0-rc3-yoctodev-standard+ #214 > [ 1.016329] Hardware name: QEMU Standard PC (Q35 + ICH9, 2009), BIOS rel-1.16.0-0-gd239552ce722-prebuilt.qemu.org 04/01/2014 > [ 1.016329] RIP: 0010:debug_print_object+0xda/0x100 > [ 1.016329] Code: 60 ec 45 92 e8 a7 7b a0 ff 4d 89 f9 4d 89 e8 44 89 e1 48 8b 14 dd 60 ec 45 92 4c 89 f6 48 c7 c7 e0 e1 45 92 e8 f9 d1 b3 00 90 <0f> e > [ 1.016329] RSP: 0000:ffff888001337bd0 EFLAGS: 00010082 > [ 1.016329] RAX: 0000000000000000 RBX: 0000000000000003 RCX: 0000000000000000 > [ 1.016329] RDX: 00000000ffffffd8 RSI: 0000000000000004 RDI: ffffed1000266f6c > [ 1.016329] RBP: ffff888001337c00 R08: ffffffff90a56ee6 R09: fffffbfff25df5c2 > [ 1.016329] R10: ffffffff92efae0b R11: fffffbfff25df5c1 R12: 0000000000000001 > [ 1.016329] R13: ffffffff9227f520 R14: ffffffff9245e640 R15: 0000000000000000 > [ 1.016329] FS: 0000000000000000(0000) GS:ffffffff92cbb000(0000) knlGS:0000000000000000 > [ 1.016329] CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033 > [ 1.016329] CR2: ffff888017401000 CR3: 0000000015a3c000 CR4: 00000000001506f0 > [ 1.016329] Call Trace: > [ 1.016329] <TASK> > [ 1.016329] debug_object_active_state+0x1d7/0x210 > [ 1.016329] ? debug_object_deactivate+0x210/0x210 > [ 1.016329] ? _raw_spin_unlock+0x23/0x30 > [ 1.016329] ? find_vmap_area+0x5c/0x90 > [ 1.016329] ? do_raw_spin_unlock+0x85/0xe0 > [ 1.016329] ? rcu_torture_fwd_cb_hist.cold+0xe9/0xe9 > [ 1.016329] call_rcu+0x39/0x150 > [ 1.016329] rcu_torture_init+0x16aa/0x1759 > [ 1.016329] ? srcu_init+0xaa/0xaa > [ 1.016329] ? irq_debugfs_copy_devname+0x70/0x70 > [ 1.016329] ? rcu_torture_barrier1cb+0x40/0x40 > [ 1.016329] ? srcu_torture_completed+0x10/0x10 > [ 1.016329] ? irq_pm_init_ops+0x19/0x19 > [ 1.016329] ? mutex_unlock+0x12/0x20 > [ 1.016329] ? srcu_init+0xaa/0xaa > [ 1.016329] do_one_initcall+0xc1/0x310 > [ 1.016329] ? initcall_blacklisted+0x140/0x140 > [ 1.016329] ? parameq+0x20/0x90 > [ 1.016329] ? __kmalloc+0x238/0x5d0 > [ 1.016329] ? rcu_read_lock_sched_held+0xe/0x50 > [ 1.016329] kernel_init_freeable+0x20a/0x268 > [ 1.016329] ? rest_init+0x160/0x160 > [ 1.016329] kernel_init+0x1e/0x140 > [ 1.016329] ret_from_fork+0x22/0x30 > [ 1.016329] </TASK> > [ 1.016329] irq event stamp: 152 > [ 1.016329] hardirqs last enabled at (151): [<ffffffff91da7a4c>] _raw_spin_unlock_irqrestore+0x4c/0x60 > [ 1.016329] hardirqs last disabled at (152): [<ffffffff91da7811>] _raw_spin_lock_irqsave+0x71/0x90 > [ 1.016329] softirqs last enabled at (0): [<ffffffff908a230c>] copy_process+0xc8c/0x31b0 > [ 1.016329] softirqs last disabled at (0): [<0000000000000000>] 0x0 > [ 1.016329] ---[ end trace 0000000000000000 ]--- > [ 1.016329] call_rcu(): Double-freed CB (____ptrval____)->rcu_torture_leak_cb+0x0/0x10()!!! slab kmalloc-16 start ffff888003f49240 pointer offset 06 > [ 1.101401] rcu-torture: rcu_torture_read_exit: Start of test > > Thanks > Zqiang > > > > > > Thanx, Paul > > > --- > > v1->v2: > > for do duplicate kvfree_call_rcu(), not set leak callbacks. > > > > kernel/rcu/tiny.c | 17 ++++++++++++++++- > > 1 file changed, 16 insertions(+), 1 deletion(-) > > > > diff --git a/kernel/rcu/tiny.c b/kernel/rcu/tiny.c > > index f0561ee16b9c..943d431b908f 100644 > > --- a/kernel/rcu/tiny.c > > +++ b/kernel/rcu/tiny.c > > @@ -158,6 +158,10 @@ void synchronize_rcu(void) > > } > > EXPORT_SYMBOL_GPL(synchronize_rcu); > > > > +static void tiny_rcu_leak_callback(struct rcu_head *rhp) > > +{ > > +} > > + > > /* > > * Post an RCU callback to be invoked after the end of an RCU grace > > * period. But since we have but one CPU, that would be after any > > @@ -165,9 +169,20 @@ EXPORT_SYMBOL_GPL(synchronize_rcu); > > */ > > void call_rcu(struct rcu_head *head, rcu_callback_t func) > > { > > + static atomic_t doublefrees; > > unsigned long flags; > > > > - debug_rcu_head_queue(head); > > + if (debug_rcu_head_queue(head)) { > > + if (atomic_inc_return(&doublefrees) < 4) { > > + pr_err("%s(): Double-freed CB %p->%pS()!!! ", __func__, head, head->func); > > + mem_dump_obj(head); > > + } > > + > > + if (!__is_kvfree_rcu_offset((unsigned long)head->func)) > > + WRITE_ONCE(head->func, tiny_rcu_leak_callback); > > + return; > > + } > > + > > head->func = func; > > head->next = NULL; > > > > -- > > 2.25.1 > >
On Wed, Jul 06, 2022 at 02:00:51AM +0000, Zhang, Qiang1 wrote: > On Fri, Jul 01, 2022 at 10:44:04AM +0800, Zqiang wrote: > > Currently, only tree RCU support leak callbacks setting when do > > duplicate call_rcu(). this commit add leak callbacks setting when > > fo duplicate call_rcu() for tiny RCU. > > > > Signed-off-by: Zqiang <qiang1.zhang@intel.com> > > >This does look plausible, thank you! > > > >What testing have you done? > > > >One important test for Tiny RCU is that the size of the kernel not > >grow without a very good reason. In this case, the added code should > >be dead code in a production build (CONFIG_DEBUG_OBJECTS_RCU_HEAD=n), > >but it is good to check. > > > >It is of course also good to check that the messages print as expected, > >which is what rcutorture.object_debug is there to help with. > > In the condition that the CONFIG_DEBUG_OBJECTS_RCU_HEAD=n, the function directly returns zero. > > #else /* !CONFIG_DEBUG_OBJECTS_RCU_HEAD */ > static inline int debug_rcu_head_queue(struct rcu_head *head) > { > return 0; > } > >Yes, like I said, the added code -should- be dead code. But there is >often a gap between "should" and "is", for example, compilers don't >always do what we would like them to. So please use the "size vmlinux" >command with and without your patch for a kernel built (both times) >with CONFIG_TINY_RCU=y and CONFIG_DEBUG_OBJECTS_RCU_HEAD==n. > >The rest of the test results look good, thank you! Hi Paul 1. CONFIG_TINY_RCU=y and CONFIG_DEBUG_OBJECTS_RCU_HEAD=y Original: text data bss dec hex filename 26291319 20160143 15212544 61664006 3aceb06 vmlinux Applay patch: text data bss dec hex filename 26291319 20160431 15212544 61664294 3acec26 vmlinux 2. CONFIG_TINY_RCU=y and CONFIG_DEBUG_OBJECTS_RCU_HEAD=n Original: text data bss dec hex filename 26290663 20159823 15212544 61663030 3ace736 vmlinux Applay patch: text data bss dec hex filename 26290663 20159823 15212544 61663030 3ace736 vmlinux Thanks Zqiang > > Thanx, Paul > > My test results are as follows: > > runqemu kvm slirp nographic qemuparams="-m 2048 -smp 1" bootparams="rcutorture.object_debug=1" -d > > log: > root@qemux86-64:/# zcat /proc/config.gz | grep RCU > # RCU Subsystem > CONFIG_TINY_RCU=y > CONFIG_DEBUG_OBJECTS_RCU_HEAD=y > > [ 1.015657] rcutorture: WARN: Duplicate call_rcu() test starting. > [ 1.015659] ------------[ cut here ]------------ > [ 1.015659] ODEBUG: activate active (active state 1) object type: rcu_head hint: 0x0 > [ 1.015680] WARNING: CPU: 0 PID: 1 at lib/debugobjects.c:502 debug_print_object+0xda/0x100 > [ 1.016329] Modules linked in: > [ 1.016329] CPU: 0 PID: 1 Comm: swapper Not tainted 5.19.0-rc3-yoctodev-standard+ #214 > [ 1.016329] Hardware name: QEMU Standard PC (Q35 + ICH9, 2009), BIOS rel-1.16.0-0-gd239552ce722-prebuilt.qemu.org 04/01/2014 > [ 1.016329] RIP: 0010:debug_print_object+0xda/0x100 > [ 1.016329] Code: 60 ec 45 92 e8 a7 7b a0 ff 4d 89 f9 4d 89 e8 44 89 e1 48 8b 14 dd 60 ec 45 92 4c 89 f6 48 c7 c7 e0 e1 45 92 e8 f9 d1 b3 00 90 <0f> e > [ 1.016329] RSP: 0000:ffff888001337be0 EFLAGS: 00010086 > [ 1.016329] RAX: 0000000000000000 RBX: 0000000000000003 RCX: 0000000000000000 > [ 1.016329] RDX: 00000000ffffffd8 RSI: 0000000000000004 RDI: ffffed1000266f6e > [ 1.016329] RBP: ffff888001337c10 R08: ffffffff90a56ee6 R09: fffffbfff25df5c2 > [ 1.016329] R10: ffffffff92efae0b R11: fffffbfff25df5c1 R12: 0000000000000001 > [ 1.016329] R13: ffffffff9227f520 R14: ffffffff9245e8a0 R15: 0000000000000000 > [ 1.016329] FS: 0000000000000000(0000) GS:ffffffff92cbb000(0000) knlGS:0000000000000000 > [ 1.016329] CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033 > [ 1.016329] CR2: ffff888017401000 CR3: 0000000015a3c000 CR4: 00000000001506f0 > [ 1.016329] Call Trace: > [ 1.016329] <TASK> > [ 1.016329] debug_object_activate+0x2b9/0x300 > [ 1.016329] ? debug_object_assert_init+0x220/0x220 > [ 1.016329] ? lockdep_hardirqs_on_prepare+0x13/0x210 > [ 1.016329] ? call_rcu+0xde/0x150 > [ 1.016329] ? trace_hardirqs_on+0x54/0x120 > [ 1.016329] ? rcu_torture_fwd_cb_hist.cold+0xe9/0xe9 > [ 1.016329] call_rcu+0x20/0x150 > [ 1.016329] rcu_torture_init+0x1687/0x1759 > [ 1.016329] ? srcu_init+0xaa/0xaa > [ 1.016329] ? irq_debugfs_copy_devname+0x70/0x70 > [ 1.016329] ? rcu_torture_barrier1cb+0x40/0x40 > [ 1.016329] ? rcu_torture_barrier1cb+0x40/0x40 > [ 1.016329] ? irq_pm_init_ops+0x19/0x19 > [ 1.016329] ? mutex_unlock+0x12/0x20 > [ 1.016329] ? srcu_init+0xaa/0xaa > [ 1.016329] do_one_initcall+0xc1/0x310 > [ 1.016329] ? initcall_blacklisted+0x140/0x140 > [ 1.016329] ? parameq+0x20/0x90 > [ 1.016329] ? __kmalloc+0x238/0x5d0 > [ 1.016329] ? rcu_read_lock_sched_held+0xe/0x50 > [ 1.016329] kernel_init_freeable+0x20a/0x268 > [ 1.016329] ? rest_init+0x160/0x160 > [ 1.016329] kernel_init+0x1e/0x140 > [ 1.016329] ret_from_fork+0x22/0x30 > [ 1.016329] </TASK> > [ 1.016329] irq event stamp: 152 > [ 1.016329] hardirqs last enabled at (151): [<ffffffff91da7a4c>] _raw_spin_unlock_irqrestore+0x4c/0x60 > [ 1.016329] hardirqs last disabled at (152): [<ffffffff91da7811>] _raw_spin_lock_irqsave+0x71/0x90 > [ 1.016329] softirqs last enabled at (0): [<ffffffff908a230c>] copy_process+0xc8c/0x31b0 > [ 1.016329] softirqs last disabled at (0): [<0000000000000000>] 0x0 > [ 1.016329] ---[ end trace 0000000000000000 ]--- > [ 1.016329] ------------[ cut here ]------------ > [ 1.016329] ODEBUG: active_state active (active state 1) object type: rcu_head hint: 0x0 > [ 1.016329] WARNING: CPU: 0 PID: 1 at lib/debugobjects.c:502 debug_print_object+0xda/0x100 > [ 1.016329] Modules linked in: > [ 1.016329] CPU: 0 PID: 1 Comm: swapper Tainted: G W 5.19.0-rc3-yoctodev-standard+ #214 > [ 1.016329] Hardware name: QEMU Standard PC (Q35 + ICH9, 2009), BIOS rel-1.16.0-0-gd239552ce722-prebuilt.qemu.org 04/01/2014 > [ 1.016329] RIP: 0010:debug_print_object+0xda/0x100 > [ 1.016329] Code: 60 ec 45 92 e8 a7 7b a0 ff 4d 89 f9 4d 89 e8 44 89 e1 48 8b 14 dd 60 ec 45 92 4c 89 f6 48 c7 c7 e0 e1 45 92 e8 f9 d1 b3 00 90 <0f> e > [ 1.016329] RSP: 0000:ffff888001337bd0 EFLAGS: 00010082 > [ 1.016329] RAX: 0000000000000000 RBX: 0000000000000003 RCX: 0000000000000000 > [ 1.016329] RDX: 00000000ffffffd8 RSI: 0000000000000004 RDI: ffffed1000266f6c > [ 1.016329] RBP: ffff888001337c00 R08: ffffffff90a56ee6 R09: fffffbfff25df5c2 > [ 1.016329] R10: ffffffff92efae0b R11: fffffbfff25df5c1 R12: 0000000000000001 > [ 1.016329] R13: ffffffff9227f520 R14: ffffffff9245e640 R15: 0000000000000000 > [ 1.016329] FS: 0000000000000000(0000) GS:ffffffff92cbb000(0000) knlGS:0000000000000000 > [ 1.016329] CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033 > [ 1.016329] CR2: ffff888017401000 CR3: 0000000015a3c000 CR4: 00000000001506f0 > [ 1.016329] Call Trace: > [ 1.016329] <TASK> > [ 1.016329] debug_object_active_state+0x1d7/0x210 > [ 1.016329] ? debug_object_deactivate+0x210/0x210 > [ 1.016329] ? lockdep_hardirqs_on_prepare+0x13/0x210 > [ 1.016329] ? call_rcu+0xde/0x150 > [ 1.016329] ? trace_hardirqs_on+0x54/0x120 > [ 1.016329] ? rcu_torture_fwd_cb_hist.cold+0xe9/0xe9 > [ 1.016329] call_rcu+0x39/0x150 > [ 1.016329] rcu_torture_init+0x1687/0x1759 > [ 1.016329] ? srcu_init+0xaa/0xaa > [ 1.016329] ? irq_debugfs_copy_devname+0x70/0x70 > [ 1.016329] ? rcu_torture_barrier1cb+0x40/0x40 > [ 1.016329] ? rcu_torture_barrier1cb+0x40/0x40 > [ 1.016329] ? irq_pm_init_ops+0x19/0x19 > [ 1.016329] ? mutex_unlock+0x12/0x20 > [ 1.016329] ? srcu_init+0xaa/0xaa > [ 1.016329] do_one_initcall+0xc1/0x310 > [ 1.016329] ? initcall_blacklisted+0x140/0x140 > [ 1.016329] ? parameq+0x20/0x90 > [ 1.016329] ? __kmalloc+0x238/0x5d0 > [ 1.016329] ? rcu_read_lock_sched_held+0xe/0x50 > [ 1.016329] kernel_init_freeable+0x20a/0x268 > [ 1.016329] ? rest_init+0x160/0x160 > [ 1.016329] kernel_init+0x1e/0x140 > [ 1.016329] ret_from_fork+0x22/0x30 > [ 1.016329] </TASK> > [ 1.016329] irq event stamp: 152 > [ 1.016329] hardirqs last enabled at (151): [<ffffffff91da7a4c>] _raw_spin_unlock_irqrestore+0x4c/0x60 > [ 1.016329] hardirqs last disabled at (152): [<ffffffff91da7811>] _raw_spin_lock_irqsave+0x71/0x90 > [ 1.016329] softirqs last enabled at (0): [<ffffffff908a230c>] copy_process+0xc8c/0x31b0 > [ 1.016329] softirqs last disabled at (0): [<0000000000000000>] 0x0 > [ 1.016329] ---[ end trace 0000000000000000 ]--- > [ 1.016329] call_rcu(): Double-freed CB (____ptrval____)->rcu_torture_leak_cb+0x0/0x10()!!! non-slab/vmalloc memory > [ 1.016329] ------------[ cut here ]------------ > [ 1.016329] ODEBUG: activate active (active state 1) object type: rcu_head hint: 0x0 > [ 1.016329] WARNING: CPU: 0 PID: 1 at lib/debugobjects.c:502 debug_print_object+0xda/0x100 > [ 1.016329] Modules linked in: > [ 1.016329] CPU: 0 PID: 1 Comm: swapper Tainted: G W 5.19.0-rc3-yoctodev-standard+ #214 > [ 1.016329] Hardware name: QEMU Standard PC (Q35 + ICH9, 2009), BIOS rel-1.16.0-0-gd239552ce722-prebuilt.qemu.org 04/01/2014 > [ 1.016329] RIP: 0010:debug_print_object+0xda/0x100 > [ 1.016329] Code: 60 ec 45 92 e8 a7 7b a0 ff 4d 89 f9 4d 89 e8 44 89 e1 48 8b 14 dd 60 ec 45 92 4c 89 f6 48 c7 c7 e0 e1 45 92 e8 f9 d1 b3 00 90 <0f> e > [ 1.016329] RSP: 0000:ffff888001337be0 EFLAGS: 00010086 > [ 1.016329] RAX: 0000000000000000 RBX: 0000000000000003 RCX: 0000000000000000 > [ 1.016329] RDX: 00000000ffffffd8 RSI: 0000000000000004 RDI: ffffed1000266f6e > [ 1.016329] RBP: ffff888001337c10 R08: ffffffff90a56ee6 R09: fffffbfff25df5c2 > [ 1.016329] R10: ffffffff92efae0b R11: fffffbfff25df5c1 R12: 0000000000000001 > [ 1.016329] R13: ffffffff9227f520 R14: ffffffff9245e8a0 R15: 0000000000000000 > [ 1.016329] FS: 0000000000000000(0000) GS:ffffffff92cbb000(0000) knlGS:0000000000000000 > [ 1.016329] CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033 > [ 1.016329] CR2: ffff888017401000 CR3: 0000000015a3c000 CR4: 00000000001506f0 > [ 1.016329] Call Trace: > [ 1.016329] <TASK> > [ 1.016329] debug_object_activate+0x2b9/0x300 > [ 1.016329] ? debug_object_assert_init+0x220/0x220 > [ 1.016329] ? _raw_spin_unlock+0x23/0x30 > [ 1.016329] ? find_vmap_area+0x5c/0x90 > [ 1.016329] ? do_raw_spin_unlock+0x85/0xe0 > [ 1.016329] ? rcu_torture_fwd_cb_hist.cold+0xe9/0xe9 > [ 1.016329] call_rcu+0x20/0x150 > [ 1.016329] rcu_torture_init+0x16aa/0x1759 > [ 1.016329] ? srcu_init+0xaa/0xaa > [ 1.016329] ? irq_debugfs_copy_devname+0x70/0x70 > [ 1.016329] ? rcu_torture_barrier1cb+0x40/0x40 > [ 1.016329] ? srcu_torture_completed+0x10/0x10 > [ 1.016329] ? irq_pm_init_ops+0x19/0x19 > [ 1.016329] ? mutex_unlock+0x12/0x20 > [ 1.016329] ? srcu_init+0xaa/0xaa > [ 1.016329] do_one_initcall+0xc1/0x310 > [ 1.016329] ? initcall_blacklisted+0x140/0x140 > [ 1.016329] ? parameq+0x20/0x90 > [ 1.016329] ? __kmalloc+0x238/0x5d0 > [ 1.016329] ? rcu_read_lock_sched_held+0xe/0x50 > [ 1.016329] kernel_init_freeable+0x20a/0x268 > [ 1.016329] ? rest_init+0x160/0x160 > [ 1.016329] kernel_init+0x1e/0x140 > [ 1.016329] ret_from_fork+0x22/0x30 > [ 1.016329] </TASK> > [ 1.016329] irq event stamp: 152 > [ 1.016329] hardirqs last enabled at (151): [<ffffffff91da7a4c>] _raw_spin_unlock_irqrestore+0x4c/0x60 > [ 1.016329] hardirqs last disabled at (152): [<ffffffff91da7811>] _raw_spin_lock_irqsave+0x71/0x90 > [ 1.016329] softirqs last enabled at (0): [<ffffffff908a230c>] copy_process+0xc8c/0x31b0 > [ 1.016329] softirqs last disabled at (0): [<0000000000000000>] 0x0 > [ 1.016329] ---[ end trace 0000000000000000 ]--- > [ 1.016329] ------------[ cut here ]------------ > [ 1.016329] ODEBUG: active_state active (active state 1) object type: rcu_head hint: 0x0 > [ 1.016329] WARNING: CPU: 0 PID: 1 at lib/debugobjects.c:502 debug_print_object+0xda/0x100 > [ 1.016329] Modules linked in: > [ 1.016329] CPU: 0 PID: 1 Comm: swapper Tainted: G W 5.19.0-rc3-yoctodev-standard+ #214 > [ 1.016329] Hardware name: QEMU Standard PC (Q35 + ICH9, 2009), BIOS rel-1.16.0-0-gd239552ce722-prebuilt.qemu.org 04/01/2014 > [ 1.016329] RIP: 0010:debug_print_object+0xda/0x100 > [ 1.016329] Code: 60 ec 45 92 e8 a7 7b a0 ff 4d 89 f9 4d 89 e8 44 89 e1 48 8b 14 dd 60 ec 45 92 4c 89 f6 48 c7 c7 e0 e1 45 92 e8 f9 d1 b3 00 90 <0f> e > [ 1.016329] RSP: 0000:ffff888001337bd0 EFLAGS: 00010082 > [ 1.016329] RAX: 0000000000000000 RBX: 0000000000000003 RCX: 0000000000000000 > [ 1.016329] RDX: 00000000ffffffd8 RSI: 0000000000000004 RDI: ffffed1000266f6c > [ 1.016329] RBP: ffff888001337c00 R08: ffffffff90a56ee6 R09: fffffbfff25df5c2 > [ 1.016329] R10: ffffffff92efae0b R11: fffffbfff25df5c1 R12: 0000000000000001 > [ 1.016329] R13: ffffffff9227f520 R14: ffffffff9245e640 R15: 0000000000000000 > [ 1.016329] FS: 0000000000000000(0000) GS:ffffffff92cbb000(0000) knlGS:0000000000000000 > [ 1.016329] CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033 > [ 1.016329] CR2: ffff888017401000 CR3: 0000000015a3c000 CR4: 00000000001506f0 > [ 1.016329] Call Trace: > [ 1.016329] <TASK> > [ 1.016329] debug_object_active_state+0x1d7/0x210 > [ 1.016329] ? debug_object_deactivate+0x210/0x210 > [ 1.016329] ? _raw_spin_unlock+0x23/0x30 > [ 1.016329] ? find_vmap_area+0x5c/0x90 > [ 1.016329] ? do_raw_spin_unlock+0x85/0xe0 > [ 1.016329] ? rcu_torture_fwd_cb_hist.cold+0xe9/0xe9 > [ 1.016329] call_rcu+0x39/0x150 > [ 1.016329] rcu_torture_init+0x16aa/0x1759 > [ 1.016329] ? srcu_init+0xaa/0xaa > [ 1.016329] ? irq_debugfs_copy_devname+0x70/0x70 > [ 1.016329] ? rcu_torture_barrier1cb+0x40/0x40 > [ 1.016329] ? srcu_torture_completed+0x10/0x10 > [ 1.016329] ? irq_pm_init_ops+0x19/0x19 > [ 1.016329] ? mutex_unlock+0x12/0x20 > [ 1.016329] ? srcu_init+0xaa/0xaa > [ 1.016329] do_one_initcall+0xc1/0x310 > [ 1.016329] ? initcall_blacklisted+0x140/0x140 > [ 1.016329] ? parameq+0x20/0x90 > [ 1.016329] ? __kmalloc+0x238/0x5d0 > [ 1.016329] ? rcu_read_lock_sched_held+0xe/0x50 > [ 1.016329] kernel_init_freeable+0x20a/0x268 > [ 1.016329] ? rest_init+0x160/0x160 > [ 1.016329] kernel_init+0x1e/0x140 > [ 1.016329] ret_from_fork+0x22/0x30 > [ 1.016329] </TASK> > [ 1.016329] irq event stamp: 152 > [ 1.016329] hardirqs last enabled at (151): [<ffffffff91da7a4c>] _raw_spin_unlock_irqrestore+0x4c/0x60 > [ 1.016329] hardirqs last disabled at (152): [<ffffffff91da7811>] _raw_spin_lock_irqsave+0x71/0x90 > [ 1.016329] softirqs last enabled at (0): [<ffffffff908a230c>] copy_process+0xc8c/0x31b0 > [ 1.016329] softirqs last disabled at (0): [<0000000000000000>] 0x0 > [ 1.016329] ---[ end trace 0000000000000000 ]--- > [ 1.016329] call_rcu(): Double-freed CB (____ptrval____)->rcu_torture_leak_cb+0x0/0x10()!!! slab kmalloc-16 start ffff888003f49240 pointer offset 06 > [ 1.101401] rcu-torture: rcu_torture_read_exit: Start of test > > Thanks > Zqiang > > > > > > Thanx, Paul > > > --- > > v1->v2: > > for do duplicate kvfree_call_rcu(), not set leak callbacks. > > > > kernel/rcu/tiny.c | 17 ++++++++++++++++- > > 1 file changed, 16 insertions(+), 1 deletion(-) > > > > diff --git a/kernel/rcu/tiny.c b/kernel/rcu/tiny.c > > index f0561ee16b9c..943d431b908f 100644 > > --- a/kernel/rcu/tiny.c > > +++ b/kernel/rcu/tiny.c > > @@ -158,6 +158,10 @@ void synchronize_rcu(void) > > } > > EXPORT_SYMBOL_GPL(synchronize_rcu); > > > > +static void tiny_rcu_leak_callback(struct rcu_head *rhp) > > +{ > > +} > > + > > /* > > * Post an RCU callback to be invoked after the end of an RCU grace > > * period. But since we have but one CPU, that would be after any > > @@ -165,9 +169,20 @@ EXPORT_SYMBOL_GPL(synchronize_rcu); > > */ > > void call_rcu(struct rcu_head *head, rcu_callback_t func) > > { > > + static atomic_t doublefrees; > > unsigned long flags; > > > > - debug_rcu_head_queue(head); > > + if (debug_rcu_head_queue(head)) { > > + if (atomic_inc_return(&doublefrees) < 4) { > > + pr_err("%s(): Double-freed CB %p->%pS()!!! ", __func__, head, head->func); > > + mem_dump_obj(head); > > + } > > + > > + if (!__is_kvfree_rcu_offset((unsigned long)head->func)) > > + WRITE_ONCE(head->func, tiny_rcu_leak_callback); > > + return; > > + } > > + > > head->func = func; > > head->next = NULL; > > > > -- > > 2.25.1 > >
On Wed, Jul 06, 2022 at 04:24:03AM +0000, Zhang, Qiang1 wrote: > > On Wed, Jul 06, 2022 at 02:00:51AM +0000, Zhang, Qiang1 wrote: > > On Fri, Jul 01, 2022 at 10:44:04AM +0800, Zqiang wrote: > > > Currently, only tree RCU support leak callbacks setting when do > > > duplicate call_rcu(). this commit add leak callbacks setting when > > > fo duplicate call_rcu() for tiny RCU. > > > > > > Signed-off-by: Zqiang <qiang1.zhang@intel.com> > > > > >This does look plausible, thank you! > > > > > >What testing have you done? > > > > > >One important test for Tiny RCU is that the size of the kernel not > > >grow without a very good reason. In this case, the added code should > > >be dead code in a production build (CONFIG_DEBUG_OBJECTS_RCU_HEAD=n), > > >but it is good to check. > > > > > >It is of course also good to check that the messages print as expected, > > >which is what rcutorture.object_debug is there to help with. > > > > In the condition that the CONFIG_DEBUG_OBJECTS_RCU_HEAD=n, the function directly returns zero. > > > > #else /* !CONFIG_DEBUG_OBJECTS_RCU_HEAD */ > > static inline int debug_rcu_head_queue(struct rcu_head *head) > > { > > return 0; > > } > > > >Yes, like I said, the added code -should- be dead code. But there is > >often a gap between "should" and "is", for example, compilers don't > >always do what we would like them to. So please use the "size vmlinux" > >command with and without your patch for a kernel built (both times) > >with CONFIG_TINY_RCU=y and CONFIG_DEBUG_OBJECTS_RCU_HEAD==n. > > > >The rest of the test results look good, thank you! > > Hi Paul > > 1. CONFIG_TINY_RCU=y and CONFIG_DEBUG_OBJECTS_RCU_HEAD=y > > Original: > text data bss dec hex filename > 26291319 20160143 15212544 61664006 3aceb06 vmlinux > > Applay patch: > text data bss dec hex filename > 26291319 20160431 15212544 61664294 3acec26 vmlinux > > 2. CONFIG_TINY_RCU=y and CONFIG_DEBUG_OBJECTS_RCU_HEAD=n > > Original: > text data bss dec hex filename > 26290663 20159823 15212544 61663030 3ace736 vmlinux > > Applay patch: > text data bss dec hex filename > 26290663 20159823 15212544 61663030 3ace736 vmlinux Much better, thank you! Please see below for the commit updated with this information and wordsmithed a bit. As always, please let me know if I messed something up. Thanx, Paul ------------------------------------------------------------------------ commit 88cea4e18ed430aa1187063450236fc00408eaac Author: Zqiang <qiang1.zhang@intel.com> Date: Fri Jul 1 10:44:04 2022 +0800 rcu: Make tiny RCU support leak callbacks for debug-object errors Currently, only Tree RCU leaks callbacks setting when it detects a duplicate call_rcu(). This commit causes Tiny RCU to also leak callbacks in this situation. Because this is Tiny RCU, kernel size is important: 1. CONFIG_TINY_RCU=y and CONFIG_DEBUG_OBJECTS_RCU_HEAD=n (Production kernel) Original: text data bss dec hex filename 26290663 20159823 15212544 61663030 3ace736 vmlinux With this commit: text data bss dec hex filename 26290663 20159823 15212544 61663030 3ace736 vmlinux 2. CONFIG_TINY_RCU=y and CONFIG_DEBUG_OBJECTS_RCU_HEAD=y (Debugging kernel) Original: text data bss dec hex filename 26291319 20160143 15212544 61664006 3aceb06 vmlinux With this commit: text data bss dec hex filename 26291319 20160431 15212544 61664294 3acec26 vmlinux These results show that the kernel size is unchanged for production kernels, as desired. Signed-off-by: Zqiang <qiang1.zhang@intel.com> Signed-off-by: Paul E. McKenney <paulmck@kernel.org> diff --git a/kernel/rcu/tiny.c b/kernel/rcu/tiny.c index f0561ee16b9c2..943d431b908f6 100644 --- a/kernel/rcu/tiny.c +++ b/kernel/rcu/tiny.c @@ -158,6 +158,10 @@ void synchronize_rcu(void) } EXPORT_SYMBOL_GPL(synchronize_rcu); +static void tiny_rcu_leak_callback(struct rcu_head *rhp) +{ +} + /* * Post an RCU callback to be invoked after the end of an RCU grace * period. But since we have but one CPU, that would be after any @@ -165,9 +169,20 @@ EXPORT_SYMBOL_GPL(synchronize_rcu); */ void call_rcu(struct rcu_head *head, rcu_callback_t func) { + static atomic_t doublefrees; unsigned long flags; - debug_rcu_head_queue(head); + if (debug_rcu_head_queue(head)) { + if (atomic_inc_return(&doublefrees) < 4) { + pr_err("%s(): Double-freed CB %p->%pS()!!! ", __func__, head, head->func); + mem_dump_obj(head); + } + + if (!__is_kvfree_rcu_offset((unsigned long)head->func)) + WRITE_ONCE(head->func, tiny_rcu_leak_callback); + return; + } + head->func = func; head->next = NULL;
diff --git a/kernel/rcu/tiny.c b/kernel/rcu/tiny.c index f0561ee16b9c..943d431b908f 100644 --- a/kernel/rcu/tiny.c +++ b/kernel/rcu/tiny.c @@ -158,6 +158,10 @@ void synchronize_rcu(void) } EXPORT_SYMBOL_GPL(synchronize_rcu); +static void tiny_rcu_leak_callback(struct rcu_head *rhp) +{ +} + /* * Post an RCU callback to be invoked after the end of an RCU grace * period. But since we have but one CPU, that would be after any @@ -165,9 +169,20 @@ EXPORT_SYMBOL_GPL(synchronize_rcu); */ void call_rcu(struct rcu_head *head, rcu_callback_t func) { + static atomic_t doublefrees; unsigned long flags; - debug_rcu_head_queue(head); + if (debug_rcu_head_queue(head)) { + if (atomic_inc_return(&doublefrees) < 4) { + pr_err("%s(): Double-freed CB %p->%pS()!!! ", __func__, head, head->func); + mem_dump_obj(head); + } + + if (!__is_kvfree_rcu_offset((unsigned long)head->func)) + WRITE_ONCE(head->func, tiny_rcu_leak_callback); + return; + } + head->func = func; head->next = NULL;
Currently, only tree RCU support leak callbacks setting when do duplicate call_rcu(). this commit add leak callbacks setting when fo duplicate call_rcu() for tiny RCU. Signed-off-by: Zqiang <qiang1.zhang@intel.com> --- v1->v2: for do duplicate kvfree_call_rcu(), not set leak callbacks. kernel/rcu/tiny.c | 17 ++++++++++++++++- 1 file changed, 16 insertions(+), 1 deletion(-)