* BUG: MAX_STACK_TRACE_ENTRIES too low! (2) @ 2019-03-29 10:42 syzbot 2019-03-30 11:10 ` syzbot 2019-03-30 21:58 ` syzbot 0 siblings, 2 replies; 19+ messages in thread From: syzbot @ 2019-03-29 10:42 UTC (permalink / raw) To: darrick.wong, linux-kernel, linux-xfs, syzkaller-bugs Hello, syzbot found the following crash on: HEAD commit: 1a9df9e2 Merge git://git.kernel.org/pub/scm/linux/kernel/g.. git tree: upstream console output: https://syzkaller.appspot.com/x/log.txt?x=14dc2f2b200000 kernel config: https://syzkaller.appspot.com/x/.config?x=8dcdce25ea72bedf dashboard link: https://syzkaller.appspot.com/bug?extid=6f39a9deb697359fe520 compiler: gcc (GCC) 9.0.0 20181231 (experimental) Unfortunately, I don't have any reproducer for this crash yet. IMPORTANT: if you fix the bug, please add the following tag to the commit: Reported-by: syzbot+6f39a9deb697359fe520@syzkaller.appspotmail.com XFS (loop4): Invalid superblock magic number BUG: MAX_STACK_TRACE_ENTRIES too low! turning off the locking correctness validator. CPU: 0 PID: 1067 Comm: syz-executor.4 Not tainted 5.1.0-rc2+ #40 Hardware name: Google Google Compute Engine/Google Compute Engine, BIOS Google 01/01/2011 Call Trace: __dump_stack lib/dump_stack.c:77 [inline] dump_stack+0x172/0x1f0 lib/dump_stack.c:113 save_trace kernel/locking/lockdep.c:467 [inline] save_trace.cold+0x14/0x19 kernel/locking/lockdep.c:437 check_prev_add.constprop.0+0x8dc/0x23c0 kernel/locking/lockdep.c:2268 check_prevs_add kernel/locking/lockdep.c:2333 [inline] validate_chain kernel/locking/lockdep.c:2714 [inline] __lock_acquire+0x239c/0x3fb0 kernel/locking/lockdep.c:3701 lock_acquire+0x16f/0x3f0 kernel/locking/lockdep.c:4211 flush_workqueue+0x126/0x14c0 kernel/workqueue.c:2774 drain_workqueue+0x1b4/0x470 kernel/workqueue.c:2939 destroy_workqueue+0x21/0x700 kernel/workqueue.c:4320 xfs_destroy_mount_workqueues+0xc5/0x1c0 fs/xfs/xfs_super.c:904 xfs_fs_fill_super+0x8e9/0x1670 fs/xfs/xfs_super.c:1786 mount_bdev+0x307/0x3c0 fs/super.c:1346 xfs_fs_mount+0x35/0x40 fs/xfs/xfs_super.c:1834 legacy_get_tree+0xf2/0x200 fs/fs_context.c:584 vfs_get_tree+0x123/0x450 fs/super.c:1481 do_new_mount fs/namespace.c:2622 [inline] do_mount+0x1436/0x2c40 fs/namespace.c:2942 ksys_mount+0xdb/0x150 fs/namespace.c:3151 __do_sys_mount fs/namespace.c:3165 [inline] __se_sys_mount fs/namespace.c:3162 [inline] __x64_sys_mount+0xbe/0x150 fs/namespace.c:3162 do_syscall_64+0x103/0x610 arch/x86/entry/common.c:290 entry_SYSCALL_64_after_hwframe+0x49/0xbe RIP: 0033:0x45ac7a Code: b8 a6 00 00 00 0f 05 48 3d 01 f0 ff ff 0f 83 2d 8e fb ff c3 66 2e 0f 1f 84 00 00 00 00 00 66 90 49 89 ca b8 a5 00 00 00 0f 05 <48> 3d 01 f0 ff ff 0f 83 0a 8e fb ff c3 66 0f 1f 84 00 00 00 00 00 RSP: 002b:00007f5a0187aa88 EFLAGS: 00000206 ORIG_RAX: 00000000000000a5 RAX: ffffffffffffffda RBX: 00007f5a0187ab40 RCX: 000000000045ac7a RDX: 00007f5a0187aae0 RSI: 00000000200006c0 RDI: 00007f5a0187ab00 RBP: 0000000000000000 R08: 00007f5a0187ab40 R09: 00007f5a0187aae0 R10: 0000000000000000 R11: 0000000000000206 R12: 0000000000000003 R13: 00000000004c6bd2 R14: 00000000004dc5b0 R15: 00000000ffffffff --- This bug is generated by a bot. It may contain errors. See https://goo.gl/tpsmEJ for more information about syzbot. syzbot engineers can be reached at syzkaller@googlegroups.com. syzbot will keep track of this bug report. See: https://goo.gl/tpsmEJ#status for how to communicate with syzbot. ^ permalink raw reply [flat|nested] 19+ messages in thread
* Re: BUG: MAX_STACK_TRACE_ENTRIES too low! (2) 2019-03-29 10:42 BUG: MAX_STACK_TRACE_ENTRIES too low! (2) syzbot @ 2019-03-30 11:10 ` syzbot 2019-03-30 21:58 ` syzbot 1 sibling, 0 replies; 19+ messages in thread From: syzbot @ 2019-03-30 11:10 UTC (permalink / raw) To: danitg, darrick.wong, dledford, jannh, jgg, leon, linux-kernel, linux-rdma, linux-xfs, roland, shamir.rabinovitch, syzkaller-bugs, xiyou.wangcong syzbot has found a reproducer for the following crash on: HEAD commit: 0e40da3e Merge tag 'kbuild-fixes-v5.1' of git://git.kernel.. git tree: upstream console output: https://syzkaller.appspot.com/x/log.txt?x=14d9123f200000 kernel config: https://syzkaller.appspot.com/x/.config?x=8dcdce25ea72bedf dashboard link: https://syzkaller.appspot.com/bug?extid=6f39a9deb697359fe520 compiler: gcc (GCC) 9.0.0 20181231 (experimental) userspace arch: i386 syz repro: https://syzkaller.appspot.com/x/repro.syz?x=1244591f200000 C reproducer: https://syzkaller.appspot.com/x/repro.c?x=12611c73200000 IMPORTANT: if you fix the bug, please add the following tag to the commit: Reported-by: syzbot+6f39a9deb697359fe520@syzkaller.appspotmail.com BUG: MAX_STACK_TRACE_ENTRIES too low! turning off the locking correctness validator. CPU: 0 PID: 678 Comm: syz-executor519 Not tainted 5.1.0-rc2+ #43 Hardware name: Google Google Compute Engine/Google Compute Engine, BIOS Google 01/01/2011 Call Trace: __dump_stack lib/dump_stack.c:77 [inline] dump_stack+0x172/0x1f0 lib/dump_stack.c:113 save_trace kernel/locking/lockdep.c:467 [inline] save_trace.cold+0x14/0x19 kernel/locking/lockdep.c:437 mark_lock+0x2fb/0x1380 kernel/locking/lockdep.c:3410 __lock_acquire+0x548/0x3fb0 kernel/locking/lockdep.c:3657 lock_acquire+0x16f/0x3f0 kernel/locking/lockdep.c:4211 flush_workqueue+0x126/0x14c0 kernel/workqueue.c:2774 drain_workqueue+0x1b4/0x470 kernel/workqueue.c:2939 destroy_workqueue+0x21/0x700 kernel/workqueue.c:4320 ucma_close+0x289/0x320 drivers/infiniband/core/ucma.c:1786 __fput+0x2e5/0x8d0 fs/file_table.c:278 ____fput+0x16/0x20 fs/file_table.c:309 task_work_run+0x14a/0x1c0 kernel/task_work.c:113 tracehook_notify_resume include/linux/tracehook.h:188 [inline] exit_to_usermode_loop+0x273/0x2c0 arch/x86/entry/common.c:166 prepare_exit_to_usermode arch/x86/entry/common.c:197 [inline] syscall_return_slowpath arch/x86/entry/common.c:268 [inline] do_syscall_32_irqs_on arch/x86/entry/common.c:341 [inline] do_fast_syscall_32+0xa9d/0xc98 arch/x86/entry/common.c:397 entry_SYSENTER_compat+0x70/0x7f arch/x86/entry/entry_64_compat.S:139 RIP: 0023:0xf7fc4869 Code: 85 d2 74 02 89 0a 5b 5d c3 8b 04 24 c3 8b 14 24 c3 8b 3c 24 c3 90 90 90 90 90 90 90 90 90 90 90 90 51 52 55 89 e5 0f 34 cd 80 <5d> 5a 59 c3 90 90 90 90 eb 0d 90 90 90 90 90 90 90 90 90 90 90 90 RSP: 002b:00000000ffc382bc EFLAGS: 00000246 ORIG_RAX: 0000000000000006 RAX: 0000000000000000 RBX: 0000000000000003 RCX: 00000000200002c0 RDX: 0000000000000004 RSI: 00000000080bc36e RDI: 00000000200002d8 RBP: 00000000ffc38308 R08: 0000000000000000 R09: 0000000000000000 R10: 0000000000000000 R11: 0000000000000000 R12: 0000000000000000 R13: 0000000000000000 R14: 0000000000000000 R15: 0000000000000000 ^ permalink raw reply [flat|nested] 19+ messages in thread
* Re: BUG: MAX_STACK_TRACE_ENTRIES too low! (2) 2019-03-29 10:42 BUG: MAX_STACK_TRACE_ENTRIES too low! (2) syzbot 2019-03-30 11:10 ` syzbot @ 2019-03-30 21:58 ` syzbot 2019-03-31 2:17 ` Bart Van Assche 1 sibling, 1 reply; 19+ messages in thread From: syzbot @ 2019-03-30 21:58 UTC (permalink / raw) To: akpm, bvanassche, danitg, darrick.wong, dledford, gustavo, jannh, jgg, johannes.berg, leon, linux-kernel, linux-rdma, linux-xfs, longman, mingo, paulmck, peterz, roland, shamir.rabinovitch, syzkaller-bugs, tglx, tj, torvalds, will.deacon, xiyou.wangcong syzbot has bisected this bug to: commit 669de8bda87b92ab9a2fc663b3f5743c2ad1ae9f Author: Bart Van Assche <bvanassche@acm.org> Date: Thu Feb 14 23:00:54 2019 +0000 kernel/workqueue: Use dynamic lockdep keys for workqueues bisection log: https://syzkaller.appspot.com/x/bisect.txt?x=17f1bacd200000 start commit: 0e40da3e Merge tag 'kbuild-fixes-v5.1' of git://git.kernel.. git tree: upstream final crash: https://syzkaller.appspot.com/x/report.txt?x=1409bacd200000 console output: https://syzkaller.appspot.com/x/log.txt?x=1009bacd200000 kernel config: https://syzkaller.appspot.com/x/.config?x=8dcdce25ea72bedf dashboard link: https://syzkaller.appspot.com/bug?extid=6f39a9deb697359fe520 syz repro: https://syzkaller.appspot.com/x/repro.syz?x=10e1bacd200000 C reproducer: https://syzkaller.appspot.com/x/repro.c?x=1120fe0f200000 Reported-by: syzbot+6f39a9deb697359fe520@syzkaller.appspotmail.com Fixes: 669de8bda87b ("kernel/workqueue: Use dynamic lockdep keys for workqueues") For information about bisection process see: https://goo.gl/tpsmEJ#bisection ^ permalink raw reply [flat|nested] 19+ messages in thread
* Re: BUG: MAX_STACK_TRACE_ENTRIES too low! (2) 2019-03-30 21:58 ` syzbot @ 2019-03-31 2:17 ` Bart Van Assche 2019-07-10 5:30 ` Eric Biggers 0 siblings, 1 reply; 19+ messages in thread From: Bart Van Assche @ 2019-03-31 2:17 UTC (permalink / raw) To: syzbot, akpm, danitg, darrick.wong, dledford, gustavo, jannh, jgg, johannes.berg, leon, linux-kernel, linux-rdma, linux-xfs, longman, mingo, paulmck, peterz, roland, shamir.rabinovitch, syzkaller-bugs, tglx, tj, torvalds, will.deacon, xiyou.wangcong, Dmitry Vyukov On 3/30/19 2:58 PM, syzbot wrote: > syzbot has bisected this bug to: > > commit 669de8bda87b92ab9a2fc663b3f5743c2ad1ae9f > Author: Bart Van Assche <bvanassche@acm.org> > Date: Thu Feb 14 23:00:54 2019 +0000 > > kernel/workqueue: Use dynamic lockdep keys for workqueues > > bisection log: https://syzkaller.appspot.com/x/bisect.txt?x=17f1bacd200000 > start commit: 0e40da3e Merge tag 'kbuild-fixes-v5.1' of > git://git.kernel.. > git tree: upstream > final crash: https://syzkaller.appspot.com/x/report.txt?x=1409bacd200000 > console output: https://syzkaller.appspot.com/x/log.txt?x=1009bacd200000 > kernel config: https://syzkaller.appspot.com/x/.config?x=8dcdce25ea72bedf > dashboard link: > https://syzkaller.appspot.com/bug?extid=6f39a9deb697359fe520 > syz repro: https://syzkaller.appspot.com/x/repro.syz?x=10e1bacd200000 > C reproducer: https://syzkaller.appspot.com/x/repro.c?x=1120fe0f200000 > > Reported-by: syzbot+6f39a9deb697359fe520@syzkaller.appspotmail.com > Fixes: 669de8bda87b ("kernel/workqueue: Use dynamic lockdep keys for > workqueues") > > For information about bisection process see: > https://goo.gl/tpsmEJ#bisection Hi Dmitry, This bisection result doesn't make sense to me. As one can see, the message "BUG: MAX_STACK_TRACE_ENTRIES too low!" does not occur in the console output the above console output URL points at. Bart. ^ permalink raw reply [flat|nested] 19+ messages in thread
* Re: BUG: MAX_STACK_TRACE_ENTRIES too low! (2) 2019-03-31 2:17 ` Bart Van Assche @ 2019-07-10 5:30 ` Eric Biggers 2019-07-10 14:19 ` Bart Van Assche 0 siblings, 1 reply; 19+ messages in thread From: Eric Biggers @ 2019-07-10 5:30 UTC (permalink / raw) To: Bart Van Assche Cc: Peter Zijlstra, Ingo Molnar, Will Deacon, linux-kernel, syzbot, syzkaller-bugs [Moved most people to Bcc; syzbot added way too many random people to this.] Hi Bart, On Sat, Mar 30, 2019 at 07:17:09PM -0700, Bart Van Assche wrote: > On 3/30/19 2:58 PM, syzbot wrote: > > syzbot has bisected this bug to: > > > > commit 669de8bda87b92ab9a2fc663b3f5743c2ad1ae9f > > Author: Bart Van Assche <bvanassche@acm.org> > > Date: Thu Feb 14 23:00:54 2019 +0000 > > > > kernel/workqueue: Use dynamic lockdep keys for workqueues > > > > bisection log: https://syzkaller.appspot.com/x/bisect.txt?x=17f1bacd200000 > > start commit: 0e40da3e Merge tag 'kbuild-fixes-v5.1' of > > git://git.kernel.. > > git tree: upstream > > final crash: https://syzkaller.appspot.com/x/report.txt?x=1409bacd200000 > > console output: https://syzkaller.appspot.com/x/log.txt?x=1009bacd200000 > > kernel config: https://syzkaller.appspot.com/x/.config?x=8dcdce25ea72bedf > > dashboard link: > > https://syzkaller.appspot.com/bug?extid=6f39a9deb697359fe520 > > syz repro: https://syzkaller.appspot.com/x/repro.syz?x=10e1bacd200000 > > C reproducer: https://syzkaller.appspot.com/x/repro.c?x=1120fe0f200000 > > > > Reported-by: syzbot+6f39a9deb697359fe520@syzkaller.appspotmail.com > > Fixes: 669de8bda87b ("kernel/workqueue: Use dynamic lockdep keys for > > workqueues") > > > > For information about bisection process see: > > https://goo.gl/tpsmEJ#bisection > > Hi Dmitry, > > This bisection result doesn't make sense to me. As one can see, the message > "BUG: MAX_STACK_TRACE_ENTRIES too low!" does not occur in the console output > the above console output URL points at. > > Bart. This is still happening on mainline, and I think this bisection result is probably correct. syzbot did start hitting something different at the very end of the bisection ("WARNING: CPU: 0 PID: 9153 at kernel/locking/lockdep.c:747") but that seems to be just because your commit had a lot of bugs in it, which had to be fixed by later commits. In particular, the WARNING seems to have been fixed by commit 28d49e282665e ("locking/lockdep: Shrink struct lock_class_key"). What seems to still be happening is that the dynamic lockdep keys which you added make it possible for an unbounded number of entries to be added to the fixed length stack_trace[] array in kernel/locking/lockdep.c. Hence the "BUG: MAX_STACK_TRACE_ENTRIES too low!". Am I understanding it correctly? How did you intend this to work? - Eric ^ permalink raw reply [flat|nested] 19+ messages in thread
* Re: BUG: MAX_STACK_TRACE_ENTRIES too low! (2) 2019-07-10 5:30 ` Eric Biggers @ 2019-07-10 14:19 ` Bart Van Assche 2019-07-10 17:00 ` Eric Biggers 0 siblings, 1 reply; 19+ messages in thread From: Bart Van Assche @ 2019-07-10 14:19 UTC (permalink / raw) To: Peter Zijlstra, Ingo Molnar, Will Deacon, linux-kernel, syzbot, syzkaller-bugs On 7/9/19 10:30 PM, Eric Biggers wrote: > [Moved most people to Bcc; syzbot added way too many random people to this.] > > Hi Bart, > > On Sat, Mar 30, 2019 at 07:17:09PM -0700, Bart Van Assche wrote: >> On 3/30/19 2:58 PM, syzbot wrote: >>> syzbot has bisected this bug to: >>> >>> commit 669de8bda87b92ab9a2fc663b3f5743c2ad1ae9f >>> Author: Bart Van Assche <bvanassche@acm.org> >>> Date: Thu Feb 14 23:00:54 2019 +0000 >>> >>> kernel/workqueue: Use dynamic lockdep keys for workqueues >>> >>> bisection log: https://syzkaller.appspot.com/x/bisect.txt?x=17f1bacd200000 >>> start commit: 0e40da3e Merge tag 'kbuild-fixes-v5.1' of >>> git://git.kernel.. >>> git tree: upstream >>> final crash: https://syzkaller.appspot.com/x/report.txt?x=1409bacd200000 >>> console output: https://syzkaller.appspot.com/x/log.txt?x=1009bacd200000 >>> kernel config: https://syzkaller.appspot.com/x/.config?x=8dcdce25ea72bedf >>> dashboard link: >>> https://syzkaller.appspot.com/bug?extid=6f39a9deb697359fe520 >>> syz repro: https://syzkaller.appspot.com/x/repro.syz?x=10e1bacd200000 >>> C reproducer: https://syzkaller.appspot.com/x/repro.c?x=1120fe0f200000 >>> >>> Reported-by: syzbot+6f39a9deb697359fe520@syzkaller.appspotmail.com >>> Fixes: 669de8bda87b ("kernel/workqueue: Use dynamic lockdep keys for >>> workqueues") >>> >>> For information about bisection process see: >>> https://goo.gl/tpsmEJ#bisection >> >> Hi Dmitry, >> >> This bisection result doesn't make sense to me. As one can see, the message >> "BUG: MAX_STACK_TRACE_ENTRIES too low!" does not occur in the console output >> the above console output URL points at. >> >> Bart. > > This is still happening on mainline, and I think this bisection result is > probably correct. syzbot did start hitting something different at the very end > of the bisection ("WARNING: CPU: 0 PID: 9153 at kernel/locking/lockdep.c:747") > but that seems to be just because your commit had a lot of bugs in it, which had > to be fixed by later commits. In particular, the WARNING seems to have been > fixed by commit 28d49e282665e ("locking/lockdep: Shrink struct lock_class_key"). > > What seems to still be happening is that the dynamic lockdep keys which you > added make it possible for an unbounded number of entries to be added to the > fixed length stack_trace[] array in kernel/locking/lockdep.c. Hence the "BUG: > MAX_STACK_TRACE_ENTRIES too low!". > > Am I understanding it correctly? How did you intend this to work? The last two paragraphs do not make sense to me. My changes do not increase the number of stack traces that get recorded by the lockdep code. Bart. ^ permalink raw reply [flat|nested] 19+ messages in thread
* Re: BUG: MAX_STACK_TRACE_ENTRIES too low! (2) 2019-07-10 14:19 ` Bart Van Assche @ 2019-07-10 17:00 ` Eric Biggers 2019-07-10 17:21 ` Eric Biggers 0 siblings, 1 reply; 19+ messages in thread From: Eric Biggers @ 2019-07-10 17:00 UTC (permalink / raw) To: Bart Van Assche Cc: Peter Zijlstra, Ingo Molnar, Will Deacon, linux-kernel, syzbot, syzkaller-bugs On Wed, Jul 10, 2019 at 07:19:55AM -0700, Bart Van Assche wrote: > On 7/9/19 10:30 PM, Eric Biggers wrote: > > [Moved most people to Bcc; syzbot added way too many random people to this.] > > > > Hi Bart, > > > > On Sat, Mar 30, 2019 at 07:17:09PM -0700, Bart Van Assche wrote: > > > On 3/30/19 2:58 PM, syzbot wrote: > > > > syzbot has bisected this bug to: > > > > > > > > commit 669de8bda87b92ab9a2fc663b3f5743c2ad1ae9f > > > > Author: Bart Van Assche <bvanassche@acm.org> > > > > Date: Thu Feb 14 23:00:54 2019 +0000 > > > > > > > > kernel/workqueue: Use dynamic lockdep keys for workqueues > > > > > > > > bisection log: https://syzkaller.appspot.com/x/bisect.txt?x=17f1bacd200000 > > > > start commit: 0e40da3e Merge tag 'kbuild-fixes-v5.1' of > > > > git://git.kernel.. > > > > git tree: upstream > > > > final crash: https://syzkaller.appspot.com/x/report.txt?x=1409bacd200000 > > > > console output: https://syzkaller.appspot.com/x/log.txt?x=1009bacd200000 > > > > kernel config: https://syzkaller.appspot.com/x/.config?x=8dcdce25ea72bedf > > > > dashboard link: > > > > https://syzkaller.appspot.com/bug?extid=6f39a9deb697359fe520 > > > > syz repro: https://syzkaller.appspot.com/x/repro.syz?x=10e1bacd200000 > > > > C reproducer: https://syzkaller.appspot.com/x/repro.c?x=1120fe0f200000 > > > > > > > > Reported-by: syzbot+6f39a9deb697359fe520@syzkaller.appspotmail.com > > > > Fixes: 669de8bda87b ("kernel/workqueue: Use dynamic lockdep keys for > > > > workqueues") > > > > > > > > For information about bisection process see: > > > > https://goo.gl/tpsmEJ#bisection > > > > > > Hi Dmitry, > > > > > > This bisection result doesn't make sense to me. As one can see, the message > > > "BUG: MAX_STACK_TRACE_ENTRIES too low!" does not occur in the console output > > > the above console output URL points at. > > > > > > Bart. > > > > This is still happening on mainline, and I think this bisection result is > > probably correct. syzbot did start hitting something different at the very end > > of the bisection ("WARNING: CPU: 0 PID: 9153 at kernel/locking/lockdep.c:747") > > but that seems to be just because your commit had a lot of bugs in it, which had > > to be fixed by later commits. In particular, the WARNING seems to have been > > fixed by commit 28d49e282665e ("locking/lockdep: Shrink struct lock_class_key"). > > > > What seems to still be happening is that the dynamic lockdep keys which you > > added make it possible for an unbounded number of entries to be added to the > > fixed length stack_trace[] array in kernel/locking/lockdep.c. Hence the "BUG: > > MAX_STACK_TRACE_ENTRIES too low!". > > > > Am I understanding it correctly? How did you intend this to work? > > The last two paragraphs do not make sense to me. My changes do not increase > the number of stack traces that get recorded by the lockdep code. > > Bart. > Interesting. How do we explain that repeatedly allocating and freeing a workqueue is causing the number of lockdep stack trace entries to grow without bound, though? This can be reproduced with the following (which I simplified from the C reproducer that syzbot generated and used for its bisection): #include <fcntl.h> #include <unistd.h> int main() { for (;;) { int fd = open("/dev/infiniband/rdma_cm", O_RDWR); close(fd); } } The workqueue is allocated in ucma_open() and freed in ucma_close(). If I run 'grep stack-trace /proc/lockdep_stats' while reproducer is running, I can see the number is growing continuously until it hits the limit. There is also a reproducer using io_uring instead of rdma_cm (https://syzkaller.appspot.com/text?tag=ReproC&x=16483bf8600000). In both cases the workqueue is associated with a file descriptor; the workqueue is allocated and freed as the file descriptor is opened and closed. Anyone have any ideas? - Eric ^ permalink raw reply [flat|nested] 19+ messages in thread
* Re: BUG: MAX_STACK_TRACE_ENTRIES too low! (2) 2019-07-10 17:00 ` Eric Biggers @ 2019-07-10 17:21 ` Eric Biggers 2019-07-10 17:46 ` Bart Van Assche 0 siblings, 1 reply; 19+ messages in thread From: Eric Biggers @ 2019-07-10 17:21 UTC (permalink / raw) To: Bart Van Assche, Peter Zijlstra, Ingo Molnar, Will Deacon, linux-kernel, syzbot, syzkaller-bugs On Wed, Jul 10, 2019 at 10:00:59AM -0700, Eric Biggers wrote: > On Wed, Jul 10, 2019 at 07:19:55AM -0700, Bart Van Assche wrote: > > On 7/9/19 10:30 PM, Eric Biggers wrote: > > > [Moved most people to Bcc; syzbot added way too many random people to this.] > > > > > > Hi Bart, > > > > > > On Sat, Mar 30, 2019 at 07:17:09PM -0700, Bart Van Assche wrote: > > > > On 3/30/19 2:58 PM, syzbot wrote: > > > > > syzbot has bisected this bug to: > > > > > > > > > > commit 669de8bda87b92ab9a2fc663b3f5743c2ad1ae9f > > > > > Author: Bart Van Assche <bvanassche@acm.org> > > > > > Date: Thu Feb 14 23:00:54 2019 +0000 > > > > > > > > > > kernel/workqueue: Use dynamic lockdep keys for workqueues > > > > > > > > > > bisection log: https://syzkaller.appspot.com/x/bisect.txt?x=17f1bacd200000 > > > > > start commit: 0e40da3e Merge tag 'kbuild-fixes-v5.1' of > > > > > git://git.kernel.. > > > > > git tree: upstream > > > > > final crash: https://syzkaller.appspot.com/x/report.txt?x=1409bacd200000 > > > > > console output: https://syzkaller.appspot.com/x/log.txt?x=1009bacd200000 > > > > > kernel config: https://syzkaller.appspot.com/x/.config?x=8dcdce25ea72bedf > > > > > dashboard link: > > > > > https://syzkaller.appspot.com/bug?extid=6f39a9deb697359fe520 > > > > > syz repro: https://syzkaller.appspot.com/x/repro.syz?x=10e1bacd200000 > > > > > C reproducer: https://syzkaller.appspot.com/x/repro.c?x=1120fe0f200000 > > > > > > > > > > Reported-by: syzbot+6f39a9deb697359fe520@syzkaller.appspotmail.com > > > > > Fixes: 669de8bda87b ("kernel/workqueue: Use dynamic lockdep keys for > > > > > workqueues") > > > > > > > > > > For information about bisection process see: > > > > > https://goo.gl/tpsmEJ#bisection > > > > > > > > Hi Dmitry, > > > > > > > > This bisection result doesn't make sense to me. As one can see, the message > > > > "BUG: MAX_STACK_TRACE_ENTRIES too low!" does not occur in the console output > > > > the above console output URL points at. > > > > > > > > Bart. > > > > > > This is still happening on mainline, and I think this bisection result is > > > probably correct. syzbot did start hitting something different at the very end > > > of the bisection ("WARNING: CPU: 0 PID: 9153 at kernel/locking/lockdep.c:747") > > > but that seems to be just because your commit had a lot of bugs in it, which had > > > to be fixed by later commits. In particular, the WARNING seems to have been > > > fixed by commit 28d49e282665e ("locking/lockdep: Shrink struct lock_class_key"). > > > > > > What seems to still be happening is that the dynamic lockdep keys which you > > > added make it possible for an unbounded number of entries to be added to the > > > fixed length stack_trace[] array in kernel/locking/lockdep.c. Hence the "BUG: > > > MAX_STACK_TRACE_ENTRIES too low!". > > > > > > Am I understanding it correctly? How did you intend this to work? > > > > The last two paragraphs do not make sense to me. My changes do not increase > > the number of stack traces that get recorded by the lockdep code. > > > > Bart. > > > > Interesting. How do we explain that repeatedly allocating and freeing a > workqueue is causing the number of lockdep stack trace entries to grow without > bound, though? > > This can be reproduced with the following (which I simplified from the C > reproducer that syzbot generated and used for its bisection): > > #include <fcntl.h> > #include <unistd.h> > > int main() > { > for (;;) { > int fd = open("/dev/infiniband/rdma_cm", O_RDWR); > > close(fd); > } > } > > The workqueue is allocated in ucma_open() and freed in ucma_close(). If I run > 'grep stack-trace /proc/lockdep_stats' while reproducer is running, I can see > the number is growing continuously until it hits the limit. > > There is also a reproducer using io_uring instead of rdma_cm > (https://syzkaller.appspot.com/text?tag=ReproC&x=16483bf8600000). > In both cases the workqueue is associated with a file descriptor; the workqueue > is allocated and freed as the file descriptor is opened and closed. > > Anyone have any ideas? > > - Eric With my simplified reproducer, on commit 669de8bda87b ("kernel/workqueue: Use dynamic lockdep keys for workqueues") I see: WARNING: CPU: 3 PID: 189 at kernel/locking/lockdep.c:747 register_lock_class+0x4f6/0x580 and then somewhat later: BUG: MAX_LOCKDEP_KEYS too low! If on top of that I cherry pick commit 28d49e282665 ("locking/lockdep: Shrink struct lock_class_key"), I see instead: BUG: MAX_STACK_TRACE_ENTRIES too low! I also see that on mainline. Alternatively, if I check out 669de8bda87b and revert it, I don't see anything. - Eric ^ permalink raw reply [flat|nested] 19+ messages in thread
* Re: BUG: MAX_STACK_TRACE_ENTRIES too low! (2) 2019-07-10 17:21 ` Eric Biggers @ 2019-07-10 17:46 ` Bart Van Assche 2019-07-10 18:02 ` Eric Biggers 0 siblings, 1 reply; 19+ messages in thread From: Bart Van Assche @ 2019-07-10 17:46 UTC (permalink / raw) To: Peter Zijlstra, Ingo Molnar, Will Deacon, linux-kernel, syzbot, syzkaller-bugs On 7/10/19 10:21 AM, Eric Biggers wrote: > With my simplified reproducer, on commit 669de8bda87b ("kernel/workqueue: Use > dynamic lockdep keys for workqueues") I see: > > WARNING: CPU: 3 PID: 189 at kernel/locking/lockdep.c:747 register_lock_class+0x4f6/0x580 > > and then somewhat later: > > BUG: MAX_LOCKDEP_KEYS too low! > > If on top of that I cherry pick commit 28d49e282665 ("locking/lockdep: Shrink > struct lock_class_key"), I see instead: > > BUG: MAX_STACK_TRACE_ENTRIES too low! > > I also see that on mainline. > > Alternatively, if I check out 669de8bda87b and revert it, I don't see anything. Hi Eric, Is the rdma_ucm code the only code that triggers the "BUG: MAX_STACK_TRACE_ENTRIES too low!" complaint or is this complaint also triggered by other kernel code? I'm asking this because I think that fixing this would require to implement garbage collection for the stack_trace[] array in the lockdep code. That would make the lockdep code slower. I don't think that making the lockdep code slower would be welcome. Bart. ^ permalink raw reply [flat|nested] 19+ messages in thread
* Re: BUG: MAX_STACK_TRACE_ENTRIES too low! (2) 2019-07-10 17:46 ` Bart Van Assche @ 2019-07-10 18:02 ` Eric Biggers 2019-07-10 18:36 ` Bart Van Assche 0 siblings, 1 reply; 19+ messages in thread From: Eric Biggers @ 2019-07-10 18:02 UTC (permalink / raw) To: Bart Van Assche Cc: Peter Zijlstra, Ingo Molnar, Will Deacon, linux-kernel, syzbot, syzkaller-bugs On Wed, Jul 10, 2019 at 10:46:00AM -0700, Bart Van Assche wrote: > On 7/10/19 10:21 AM, Eric Biggers wrote: > > With my simplified reproducer, on commit 669de8bda87b ("kernel/workqueue: Use > > dynamic lockdep keys for workqueues") I see: > > > > WARNING: CPU: 3 PID: 189 at kernel/locking/lockdep.c:747 register_lock_class+0x4f6/0x580 > > > > and then somewhat later: > > > > BUG: MAX_LOCKDEP_KEYS too low! > > > > If on top of that I cherry pick commit 28d49e282665 ("locking/lockdep: Shrink > > struct lock_class_key"), I see instead: > > > > BUG: MAX_STACK_TRACE_ENTRIES too low! > > > > I also see that on mainline. > > > > Alternatively, if I check out 669de8bda87b and revert it, I don't see anything. > > Hi Eric, > > Is the rdma_ucm code the only code that triggers the "BUG: > MAX_STACK_TRACE_ENTRIES too low!" complaint or is this complaint also > triggered by other kernel code? I'm asking this because I think that > fixing this would require to implement garbage collection for the > stack_trace[] array in the lockdep code. That would make the lockdep > code slower. I don't think that making the lockdep code slower would be > welcome. > > Bart. I already mentioned that io_uring triggers it too. Those are just 2 cases that syzbot happened to generate reproducers for. I expect there are many others too, since many places in the kernel allocate workqueues. AFAICS most are placed in static or global variables which avoids this issue, but there are still many cases where a workqueue is owned by some dynamic structure that can have a much shorter lifetime. You can also check the other syzbot reports that look similar (https://lore.kernel.org/lkml/20190710055838.GC2152@sol.localdomain/). Two of them have C reproducers too. - Eric ^ permalink raw reply [flat|nested] 19+ messages in thread
* Re: BUG: MAX_STACK_TRACE_ENTRIES too low! (2) 2019-07-10 18:02 ` Eric Biggers @ 2019-07-10 18:36 ` Bart Van Assche 2019-07-10 18:44 ` Eric Dumazet 0 siblings, 1 reply; 19+ messages in thread From: Bart Van Assche @ 2019-07-10 18:36 UTC (permalink / raw) To: Peter Zijlstra, Ingo Molnar, Will Deacon, linux-kernel, syzbot, syzkaller-bugs On 7/10/19 11:02 AM, Eric Biggers wrote: > I already mentioned that io_uring triggers it too. > > Those are just 2 cases that syzbot happened to generate reproducers for. I > expect there are many others too, since many places in the kernel allocate > workqueues. AFAICS most are placed in static or global variables which avoids > this issue, but there are still many cases where a workqueue is owned by some > dynamic structure that can have a much shorter lifetime. > > You can also check the other syzbot reports that look similar > (https://lore.kernel.org/lkml/20190710055838.GC2152@sol.localdomain/). > Two of them have C reproducers too. As you may know lockdep cannot use dynamic memory allocation because doing so would introduce a circular dependency between lockdep and the memory allocator. Hence the fixed size arrays in the lockdep code. Additionally, as far as I know lockdep works fine for human kernel developers and only syzbot runs code that triggers the lockdep limits. So I think it's up to the syzbot authors to come up with a solution. I mean another solution than finger pointing at kernel developers. Bart. ^ permalink raw reply [flat|nested] 19+ messages in thread
* Re: BUG: MAX_STACK_TRACE_ENTRIES too low! (2) 2019-07-10 18:36 ` Bart Van Assche @ 2019-07-10 18:44 ` Eric Dumazet 2019-07-10 19:09 ` Bart Van Assche 0 siblings, 1 reply; 19+ messages in thread From: Eric Dumazet @ 2019-07-10 18:44 UTC (permalink / raw) To: Bart Van Assche, Peter Zijlstra, Ingo Molnar, Will Deacon, linux-kernel, syzbot, syzkaller-bugs On 7/10/19 8:36 PM, Bart Van Assche wrote: > On 7/10/19 11:02 AM, Eric Biggers wrote: >> I already mentioned that io_uring triggers it too. >> >> Those are just 2 cases that syzbot happened to generate reproducers for. I >> expect there are many others too, since many places in the kernel allocate >> workqueues. AFAICS most are placed in static or global variables which avoids >> this issue, but there are still many cases where a workqueue is owned by some >> dynamic structure that can have a much shorter lifetime. >> >> You can also check the other syzbot reports that look similar >> (https://lore.kernel.org/lkml/20190710055838.GC2152@sol.localdomain/). >> Two of them have C reproducers too. > > As you may know lockdep cannot use dynamic memory allocation because > doing so would introduce a circular dependency between lockdep and the > memory allocator. Hence the fixed size arrays in the lockdep code. > Additionally, as far as I know lockdep works fine for human kernel > developers and only syzbot runs code that triggers the lockdep limits. > So I think it's up to the syzbot authors to come up with a solution. I > mean another solution than finger pointing at kernel developers. This is silly, syzbot simply uses kernel standard system calls. If anything using workqueues in dynamically allocated objects can turn off lockdep, we have a serious issue. Please work on this issue instead of trying to blame someone else. Thank you. ^ permalink raw reply [flat|nested] 19+ messages in thread
* Re: BUG: MAX_STACK_TRACE_ENTRIES too low! (2) 2019-07-10 18:44 ` Eric Dumazet @ 2019-07-10 19:09 ` Bart Van Assche 2019-07-10 20:47 ` Eric Dumazet 0 siblings, 1 reply; 19+ messages in thread From: Bart Van Assche @ 2019-07-10 19:09 UTC (permalink / raw) To: Eric Dumazet, Peter Zijlstra, Ingo Molnar, Will Deacon, linux-kernel, syzbot, syzkaller-bugs On 7/10/19 11:44 AM, Eric Dumazet wrote: > If anything using workqueues in dynamically allocated objects can turn off lockdep, > we have a serious issue. As far as I know that issue is only hit by syzbot tests. Anyway, I see two possible paths forward: * Revert the patch that makes workqueues use dynamic lockdep keys and thereby reintroduce the false positives that lockdep reports if different workqueues share a lockdep key. I think there is agreement that having to analyze lockdep false positives is annoying, time consuming and something nobody likes. * Modify lockdep such that space in its fixed size arrays that is no longer in use gets reused. Since the stack traces saved in the stack_trace[] array have a variable size that array will have to be compacted to avoid fragmentation. Did I overlook anything? Bart. ^ permalink raw reply [flat|nested] 19+ messages in thread
* Re: BUG: MAX_STACK_TRACE_ENTRIES too low! (2) 2019-07-10 19:09 ` Bart Van Assche @ 2019-07-10 20:47 ` Eric Dumazet 2019-07-10 21:23 ` Bart Van Assche 0 siblings, 1 reply; 19+ messages in thread From: Eric Dumazet @ 2019-07-10 20:47 UTC (permalink / raw) To: Bart Van Assche, Eric Dumazet, Peter Zijlstra, Ingo Molnar, Will Deacon, linux-kernel, syzbot, syzkaller-bugs On 7/10/19 9:09 PM, Bart Van Assche wrote: > On 7/10/19 11:44 AM, Eric Dumazet wrote: >> If anything using workqueues in dynamically allocated objects can turn off lockdep, >> we have a serious issue. > > As far as I know that issue is only hit by syzbot tests. > Anyway, I see > two possible paths forward: > * Revert the patch that makes workqueues use dynamic lockdep keys and > thereby reintroduce the false positives that lockdep reports if > different workqueues share a lockdep key. I think there is agreement > that having to analyze lockdep false positives is annoying, time > consuming and something nobody likes. > * Modify lockdep such that space in its fixed size arrays that is no > longer in use gets reused. Since the stack traces saved in the > stack_trace[] array have a variable size that array will have to be > compacted to avoid fragmentation. > Can not destroy_workqueue() undo what alloc_workqueue() did ? ^ permalink raw reply [flat|nested] 19+ messages in thread
* Re: BUG: MAX_STACK_TRACE_ENTRIES too low! (2) 2019-07-10 20:47 ` Eric Dumazet @ 2019-07-10 21:23 ` Bart Van Assche 2019-07-10 22:09 ` Peter Zijlstra 0 siblings, 1 reply; 19+ messages in thread From: Bart Van Assche @ 2019-07-10 21:23 UTC (permalink / raw) To: Eric Dumazet, Peter Zijlstra, Ingo Molnar, Will Deacon, linux-kernel, syzbot, syzkaller-bugs On 7/10/19 1:47 PM, Eric Dumazet wrote: > > > On 7/10/19 9:09 PM, Bart Van Assche wrote: >> On 7/10/19 11:44 AM, Eric Dumazet wrote: >>> If anything using workqueues in dynamically allocated objects can turn off lockdep, >>> we have a serious issue. >> >> As far as I know that issue is only hit by syzbot tests. > > > >> Anyway, I see >> two possible paths forward: >> * Revert the patch that makes workqueues use dynamic lockdep keys and >> thereby reintroduce the false positives that lockdep reports if >> different workqueues share a lockdep key. I think there is agreement >> that having to analyze lockdep false positives is annoying, time >> consuming and something nobody likes. >> * Modify lockdep such that space in its fixed size arrays that is no >> longer in use gets reused. Since the stack traces saved in the >> stack_trace[] array have a variable size that array will have to be >> compacted to avoid fragmentation. >> > > Can not destroy_workqueue() undo what alloc_workqueue() did ? destroy_workqueue() already calls lockdep_unregister_key(). If that wouldn't happen then sooner or later one of the warning statements in the lockdep code would be triggered, e.g. the WARN_ON_ONCE() statement in lockdep_register_key(). I think the root cause is that lockdep_unregister_key() does not free the stack traces recorded by the lockdep save_trace() function. save_trace() is called every time a lock is acquired and lockdep encounters a new lock dependency chain. As one can see in remove_class_from_lock_chain() there is already code present in lockdep for compacting the chain_hlocks[] array. Similar code is not yet available for the stack_trace[] array because I had not encountered any overflows of that array during my tests. Bart. ^ permalink raw reply [flat|nested] 19+ messages in thread
* Re: BUG: MAX_STACK_TRACE_ENTRIES too low! (2) 2019-07-10 21:23 ` Bart Van Assche @ 2019-07-10 22:09 ` Peter Zijlstra 2019-07-11 18:53 ` Bart Van Assche 0 siblings, 1 reply; 19+ messages in thread From: Peter Zijlstra @ 2019-07-10 22:09 UTC (permalink / raw) To: Bart Van Assche Cc: Eric Dumazet, Ingo Molnar, Will Deacon, linux-kernel, syzbot, syzkaller-bugs On Wed, Jul 10, 2019 at 02:23:39PM -0700, Bart Van Assche wrote: > As one can see in remove_class_from_lock_chain() there is already code > present in lockdep for compacting the chain_hlocks[] array. Similar code > is not yet available for the stack_trace[] array because I had not > encountered any overflows of that array during my tests. One thing I mentioned when Thomas did the unwinder API changes was trying to move lockdep over to something like stackdepot. We can't directly use stackdepot as is, because it uses locks and memory allocation, but we could maybe add a lower level API to it and use that under the graph_lock() on static storage or something. Otherwise we'll have to (re)implement something like it. I've not looked at it in detail. ^ permalink raw reply [flat|nested] 19+ messages in thread
* Re: BUG: MAX_STACK_TRACE_ENTRIES too low! (2) 2019-07-10 22:09 ` Peter Zijlstra @ 2019-07-11 18:53 ` Bart Van Assche 2019-07-12 8:55 ` Peter Zijlstra 0 siblings, 1 reply; 19+ messages in thread From: Bart Van Assche @ 2019-07-11 18:53 UTC (permalink / raw) To: Peter Zijlstra Cc: Eric Dumazet, Ingo Molnar, Will Deacon, linux-kernel, syzbot, syzkaller-bugs On 7/10/19 3:09 PM, Peter Zijlstra wrote: > One thing I mentioned when Thomas did the unwinder API changes was > trying to move lockdep over to something like stackdepot. > > We can't directly use stackdepot as is, because it uses locks and memory > allocation, but we could maybe add a lower level API to it and use that > under the graph_lock() on static storage or something. > > Otherwise we'll have to (re)implement something like it. > > I've not looked at it in detail. Hi Peter, Is something like the untested patch below perhaps what you had in mind? Thanks, Bart. diff --git a/include/linux/lockdep.h b/include/linux/lockdep.h index 57baa27f238c..a5c7c1813d35 100644 --- a/include/linux/lockdep.h +++ b/include/linux/lockdep.h @@ -66,10 +66,7 @@ struct lock_class_key { extern struct lock_class_key __lockdep_no_validate__; -struct lock_trace { - unsigned int nr_entries; - unsigned int offset; -}; +struct lock_trace; #define LOCKSTAT_POINTS 4 @@ -105,7 +102,7 @@ struct lock_class { * IRQ/softirq usage tracking bits: */ unsigned long usage_mask; - struct lock_trace usage_traces[XXX_LOCK_USAGE_STATES]; + const struct lock_trace *usage_traces[XXX_LOCK_USAGE_STATES]; /* * Generation counter, when doing certain classes of graph walking, @@ -193,7 +190,7 @@ struct lock_list { struct list_head entry; struct lock_class *class; struct lock_class *links_to; - struct lock_trace trace; + const struct lock_trace *trace; int distance; /* diff --git a/kernel/locking/lockdep.c b/kernel/locking/lockdep.c index 341f52117f88..c3022367ba2a 100644 --- a/kernel/locking/lockdep.c +++ b/kernel/locking/lockdep.c @@ -449,33 +449,72 @@ static void print_lockdep_off(const char *bug_msg) unsigned long nr_stack_trace_entries; #if defined(CONFIG_TRACE_IRQFLAGS) && defined(CONFIG_PROVE_LOCKING) +/** + * struct lock_trace - single stack backtrace + * @hash_entry: Entry in a stack_trace_hash[] list. + * @hash: jhash() of @entries. + * @nr_entries: Number of entries in @entries. + * @entries: Actual stack backtrace. + */ +struct lock_trace { + struct hlist_node hash_entry; + u32 hash; + u32 nr_entries; + unsigned long entries[0] __aligned(sizeof(unsigned long)); +}; +#define LOCK_TRACE_SIZE_IN_LONGS \ + (sizeof(struct lock_trace) / sizeof(unsigned long)) /* - * Stack-trace: tightly packed array of stack backtrace - * addresses. Protected by the graph_lock. + * Stack-trace: sequence of lock_trace structures. Protected by the graph_lock. */ static unsigned long stack_trace[MAX_STACK_TRACE_ENTRIES]; +static struct hlist_head stack_trace_hash[STACK_TRACE_HASH_SIZE]; + +static bool traces_identical(struct lock_trace *t1, struct lock_trace *t2) +{ + return t1->hash == t2->hash && t1->nr_entries == t2->nr_entries && + memcmp(t1->entries, t2->entries, + t1->nr_entries * sizeof(t1->entries[0])) == 0; +} -static int save_trace(struct lock_trace *trace) +static struct lock_trace *save_trace(void) { - unsigned long *entries = stack_trace + nr_stack_trace_entries; + struct lock_trace *trace, *t2; + struct hlist_head *hash_head; + u32 hash; unsigned int max_entries; - trace->offset = nr_stack_trace_entries; - max_entries = MAX_STACK_TRACE_ENTRIES - nr_stack_trace_entries; - trace->nr_entries = stack_trace_save(entries, max_entries, 3); - nr_stack_trace_entries += trace->nr_entries; + BUILD_BUG_ON_NOT_POWER_OF_2(STACK_TRACE_HASH_SIZE); + BUILD_BUG_ON(LOCK_TRACE_SIZE_IN_LONGS >= MAX_STACK_TRACE_ENTRIES); + + trace = (struct lock_trace *)(stack_trace + nr_stack_trace_entries); + max_entries = MAX_STACK_TRACE_ENTRIES - nr_stack_trace_entries - + LOCK_TRACE_SIZE_IN_LONGS; + trace->nr_entries = stack_trace_save(trace->entries, max_entries, 3); - if (nr_stack_trace_entries >= MAX_STACK_TRACE_ENTRIES-1) { + if (nr_stack_trace_entries >= MAX_STACK_TRACE_ENTRIES - + LOCK_TRACE_SIZE_IN_LONGS - 1) { if (!debug_locks_off_graph_unlock()) - return 0; + return NULL; print_lockdep_off("BUG: MAX_STACK_TRACE_ENTRIES too low!"); dump_stack(); - return 0; + return NULL; } - return 1; + hash = jhash(trace->entries, trace->nr_entries * + sizeof(trace->entries[0]), 0); + trace->hash = hash; + hash_head = stack_trace_hash + (hash & (STACK_TRACE_HASH_SIZE - 1)); + hlist_for_each_entry(t2, hash_head, hash_entry) { + if (traces_identical(trace, t2)) + return t2; + } + nr_stack_trace_entries += LOCK_TRACE_SIZE_IN_LONGS + trace->nr_entries; + hlist_add_head(&trace->hash_entry, hash_head); + + return trace; } #endif @@ -1235,7 +1274,7 @@ static struct lock_list *alloc_list_entry(void) static int add_lock_to_list(struct lock_class *this, struct lock_class *links_to, struct list_head *head, unsigned long ip, int distance, - struct lock_trace *trace) + const struct lock_trace *trace) { struct lock_list *entry; /* @@ -1249,7 +1288,7 @@ static int add_lock_to_list(struct lock_class *this, entry->class = this; entry->links_to = links_to; entry->distance = distance; - entry->trace = *trace; + entry->trace = trace; /* * Both allocation and removal are done under the graph lock; but * iteration is under RCU-sched; see look_up_lock_class() and @@ -1470,11 +1509,10 @@ static inline int __bfs_backwards(struct lock_list *src_entry, } -static void print_lock_trace(struct lock_trace *trace, unsigned int spaces) +static void print_lock_trace(const struct lock_trace *trace, + unsigned int spaces) { - unsigned long *entries = stack_trace + trace->offset; - - stack_trace_print(entries, trace->nr_entries, spaces); + stack_trace_print(trace->entries, trace->nr_entries, spaces); } /* @@ -1489,7 +1527,7 @@ print_circular_bug_entry(struct lock_list *target, int depth) printk("\n-> #%u", depth); print_lock_name(target->class); printk(KERN_CONT ":\n"); - print_lock_trace(&target->trace, 6); + print_lock_trace(target->trace, 6); } static void @@ -1592,7 +1630,8 @@ static noinline void print_circular_bug(struct lock_list *this, if (!debug_locks_off_graph_unlock() || debug_locks_silent) return; - if (!save_trace(&this->trace)) + this->trace = save_trace(); + if (!this->trace) return; depth = get_lock_depth(target); @@ -1715,7 +1754,7 @@ check_path(struct lock_class *target, struct lock_list *src_entry, */ static noinline int check_noncircular(struct held_lock *src, struct held_lock *target, - struct lock_trace *trace) + struct lock_trace **const trace) { int ret; struct lock_list *uninitialized_var(target_entry); @@ -1729,13 +1768,13 @@ check_noncircular(struct held_lock *src, struct held_lock *target, ret = check_path(hlock_class(target), &src_entry, &target_entry); if (unlikely(!ret)) { - if (!trace->nr_entries) { + if (!*trace) { /* * If save_trace fails here, the printing might * trigger a WARN but because of the !nr_entries it * should not do bad things. */ - save_trace(trace); + *trace = save_trace(); } print_circular_bug(&src_entry, target_entry, src, target); @@ -1859,7 +1898,7 @@ static void print_lock_class_header(struct lock_class *class, int depth) len += printk("%*s %s", depth, "", usage_str[bit]); len += printk(KERN_CONT " at:\n"); - print_lock_trace(class->usage_traces + bit, len); + print_lock_trace(class->usage_traces[bit], len); } } printk("%*s }\n", depth, ""); @@ -1884,7 +1923,7 @@ print_shortest_lock_dependencies(struct lock_list *leaf, do { print_lock_class_header(entry->class, depth); printk("%*s ... acquired at:\n", depth, ""); - print_lock_trace(&entry->trace, 2); + print_lock_trace(entry->trace, 2); printk("\n"); if (depth == 0 && (entry != root)) { @@ -1995,14 +2034,14 @@ print_bad_irq_dependency(struct task_struct *curr, print_lock_name(backwards_entry->class); pr_warn("\n... which became %s-irq-safe at:\n", irqclass); - print_lock_trace(backwards_entry->class->usage_traces + bit1, 1); + print_lock_trace(backwards_entry->class->usage_traces[bit1], 1); pr_warn("\nto a %s-irq-unsafe lock:\n", irqclass); print_lock_name(forwards_entry->class); pr_warn("\n... which became %s-irq-unsafe at:\n", irqclass); pr_warn("..."); - print_lock_trace(forwards_entry->class->usage_traces + bit2, 1); + print_lock_trace(forwards_entry->class->usage_traces[bit2], 1); pr_warn("\nother info that might help us debug this:\n\n"); print_irq_lock_scenario(backwards_entry, forwards_entry, @@ -2011,13 +2050,15 @@ print_bad_irq_dependency(struct task_struct *curr, lockdep_print_held_locks(curr); pr_warn("\nthe dependencies between %s-irq-safe lock and the holding lock:\n", irqclass); - if (!save_trace(&prev_root->trace)) + prev_root->trace = save_trace(); + if (!prev_root->trace) return; print_shortest_lock_dependencies(backwards_entry, prev_root); pr_warn("\nthe dependencies between the lock to be acquired"); pr_warn(" and %s-irq-unsafe lock:\n", irqclass); - if (!save_trace(&next_root->trace)) + next_root->trace = save_trace(); + if (!next_root->trace) return; print_shortest_lock_dependencies(forwards_entry, next_root); @@ -2369,7 +2410,8 @@ check_deadlock(struct task_struct *curr, struct held_lock *next) */ static int check_prev_add(struct task_struct *curr, struct held_lock *prev, - struct held_lock *next, int distance, struct lock_trace *trace) + struct held_lock *next, int distance, + struct lock_trace **const trace) { struct lock_list *entry; int ret; @@ -2444,8 +2486,11 @@ check_prev_add(struct task_struct *curr, struct held_lock *prev, return ret; #endif - if (!trace->nr_entries && !save_trace(trace)) - return 0; + if (!*trace) { + *trace = save_trace(); + if (!*trace) + return 0; + } /* * Ok, all validations passed, add the new lock @@ -2453,14 +2498,14 @@ check_prev_add(struct task_struct *curr, struct held_lock *prev, */ ret = add_lock_to_list(hlock_class(next), hlock_class(prev), &hlock_class(prev)->locks_after, - next->acquire_ip, distance, trace); + next->acquire_ip, distance, *trace); if (!ret) return 0; ret = add_lock_to_list(hlock_class(prev), hlock_class(next), &hlock_class(next)->locks_before, - next->acquire_ip, distance, trace); + next->acquire_ip, distance, *trace); if (!ret) return 0; @@ -2476,7 +2521,7 @@ check_prev_add(struct task_struct *curr, struct held_lock *prev, static int check_prevs_add(struct task_struct *curr, struct held_lock *next) { - struct lock_trace trace = { .nr_entries = 0 }; + struct lock_trace *trace = NULL; int depth = curr->lockdep_depth; struct held_lock *hlock; @@ -3015,7 +3060,7 @@ print_usage_bug(struct task_struct *curr, struct held_lock *this, print_lock(this); pr_warn("{%s} state was registered at:\n", usage_str[prev_bit]); - print_lock_trace(hlock_class(this)->usage_traces + prev_bit, 1); + print_lock_trace(hlock_class(this)->usage_traces[prev_bit], 1); print_irqtrace_events(curr); pr_warn("\nother info that might help us debug this:\n"); @@ -3096,7 +3141,8 @@ print_irq_inversion_bug(struct task_struct *curr, lockdep_print_held_locks(curr); pr_warn("\nthe shortest dependencies between 2nd lock and 1st lock:\n"); - if (!save_trace(&root->trace)) + root->trace = save_trace(); + if (!root->trace) return; print_shortest_lock_dependencies(other, root); @@ -3580,7 +3626,7 @@ static int mark_lock(struct task_struct *curr, struct held_lock *this, hlock_class(this)->usage_mask |= new_mask; - if (!save_trace(hlock_class(this)->usage_traces + new_bit)) + if (!(hlock_class(this)->usage_traces[new_bit] = save_trace())) return 0; switch (new_bit) { @@ -5158,6 +5204,12 @@ void __init lockdep_init(void) ) / 1024 ); +#if defined(CONFIG_TRACE_IRQFLAGS) && defined(CONFIG_PROVE_LOCKING) + printk(" memory used for stack traces: %zu kB\n", + (sizeof(stack_trace) + sizeof(stack_trace_hash)) / 1024 + ); +#endif + printk(" per task-struct memory footprint: %zu bytes\n", sizeof(((struct task_struct *)NULL)->held_locks)); } diff --git a/kernel/locking/lockdep_internals.h b/kernel/locking/lockdep_internals.h index cc83568d5012..92c472fb838f 100644 --- a/kernel/locking/lockdep_internals.h +++ b/kernel/locking/lockdep_internals.h @@ -92,6 +92,7 @@ static const unsigned long LOCKF_USED_IN_IRQ_READ = #define MAX_LOCKDEP_ENTRIES 16384UL #define MAX_LOCKDEP_CHAINS_BITS 15 #define MAX_STACK_TRACE_ENTRIES 262144UL +#define STACK_TRACE_HASH_SIZE 8192 #else #define MAX_LOCKDEP_ENTRIES 32768UL @@ -102,6 +103,7 @@ static const unsigned long LOCKF_USED_IN_IRQ_READ = * addresses. Protected by the hash_lock. */ #define MAX_STACK_TRACE_ENTRIES 524288UL +#define STACK_TRACE_HASH_SIZE 16384 #endif #define MAX_LOCKDEP_CHAINS (1UL << MAX_LOCKDEP_CHAINS_BITS) ^ permalink raw reply related [flat|nested] 19+ messages in thread
* Re: BUG: MAX_STACK_TRACE_ENTRIES too low! (2) 2019-07-11 18:53 ` Bart Van Assche @ 2019-07-12 8:55 ` Peter Zijlstra 2019-07-12 23:03 ` Bart Van Assche 0 siblings, 1 reply; 19+ messages in thread From: Peter Zijlstra @ 2019-07-12 8:55 UTC (permalink / raw) To: Bart Van Assche Cc: Eric Dumazet, Ingo Molnar, Will Deacon, linux-kernel, syzbot, syzkaller-bugs On Thu, Jul 11, 2019 at 11:53:12AM -0700, Bart Van Assche wrote: > On 7/10/19 3:09 PM, Peter Zijlstra wrote: > > One thing I mentioned when Thomas did the unwinder API changes was > > trying to move lockdep over to something like stackdepot. > > > > We can't directly use stackdepot as is, because it uses locks and memory > > allocation, but we could maybe add a lower level API to it and use that > > under the graph_lock() on static storage or something. > > > > Otherwise we'll have to (re)implement something like it. > > > > I've not looked at it in detail. > > Hi Peter, > > Is something like the untested patch below perhaps what you had in mind? Most excellent, yes! Now I suppose the $64000 question is if it actually reduces the amount of storage we use for stack traces.. Seems to boot just fine.. :-) ^ permalink raw reply [flat|nested] 19+ messages in thread
* Re: BUG: MAX_STACK_TRACE_ENTRIES too low! (2) 2019-07-12 8:55 ` Peter Zijlstra @ 2019-07-12 23:03 ` Bart Van Assche 0 siblings, 0 replies; 19+ messages in thread From: Bart Van Assche @ 2019-07-12 23:03 UTC (permalink / raw) To: Peter Zijlstra Cc: Eric Dumazet, Ingo Molnar, Will Deacon, linux-kernel, syzbot, syzkaller-bugs On 7/12/19 1:55 AM, Peter Zijlstra wrote: > On Thu, Jul 11, 2019 at 11:53:12AM -0700, Bart Van Assche wrote: >> On 7/10/19 3:09 PM, Peter Zijlstra wrote: >>> One thing I mentioned when Thomas did the unwinder API changes was >>> trying to move lockdep over to something like stackdepot. >>> >>> We can't directly use stackdepot as is, because it uses locks and memory >>> allocation, but we could maybe add a lower level API to it and use that >>> under the graph_lock() on static storage or something. >>> >>> Otherwise we'll have to (re)implement something like it. >>> >>> I've not looked at it in detail. >> >> Hi Peter, >> >> Is something like the untested patch below perhaps what you had in mind? > > Most excellent, yes! Now I suppose the $64000 question is if it actually > reduces the amount of storage we use for stack traces.. > > Seems to boot just fine.. :-) Hi Peter, On my setup after some time the space occupied by stack traces stabilizes to the following: # grep stack /proc/lockdep_stats stack-trace entries: 169456 [max: 524288] number of stack traces: 9073 number of stack hash chains: 6980 I think these numbers show that there are some but not too many hash collisions (the code for the hash statistics was added after I e-mailed my patch). Bart. ^ permalink raw reply [flat|nested] 19+ messages in thread
end of thread, other threads:[~2019-07-12 23:03 UTC | newest] Thread overview: 19+ messages (download: mbox.gz / follow: Atom feed) -- links below jump to the message on this page -- 2019-03-29 10:42 BUG: MAX_STACK_TRACE_ENTRIES too low! (2) syzbot 2019-03-30 11:10 ` syzbot 2019-03-30 21:58 ` syzbot 2019-03-31 2:17 ` Bart Van Assche 2019-07-10 5:30 ` Eric Biggers 2019-07-10 14:19 ` Bart Van Assche 2019-07-10 17:00 ` Eric Biggers 2019-07-10 17:21 ` Eric Biggers 2019-07-10 17:46 ` Bart Van Assche 2019-07-10 18:02 ` Eric Biggers 2019-07-10 18:36 ` Bart Van Assche 2019-07-10 18:44 ` Eric Dumazet 2019-07-10 19:09 ` Bart Van Assche 2019-07-10 20:47 ` Eric Dumazet 2019-07-10 21:23 ` Bart Van Assche 2019-07-10 22:09 ` Peter Zijlstra 2019-07-11 18:53 ` Bart Van Assche 2019-07-12 8:55 ` Peter Zijlstra 2019-07-12 23:03 ` Bart Van Assche
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).