Re: [PATCH] locking/ww_mutex: Adjust to lockdep nest_lock requirements

From: kernel test robot
Date: Fri Dec 22 2023 - 04:19:26 EST




Hello,

kernel test robot noticed "WARNING:at_kernel/locking/lockdep.c:#__lock_acquire" on:

commit: 4f37585fa02f3eaebc72efa1260e6742478c00fa ("[PATCH] locking/ww_mutex: Adjust to lockdep nest_lock requirements")
url: https://github.com/intel-lab-lkp/linux/commits/Thomas-Hellstr-m/locking-ww_mutex-Adjust-to-lockdep-nest_lock-requirements/20231220-000906
base: https://git.kernel.org/cgit/linux/kernel/git/tip/tip.git a51749ab34d9e5dec548fe38ede7e01e8bb26454
patch link: https://lore.kernel.org/all/20231219160524.3646-1-thomas.hellstrom@xxxxxxxxxxxxxxx/
patch subject: [PATCH] locking/ww_mutex: Adjust to lockdep nest_lock requirements

in testcase: boot

compiler: gcc-7
test machine: qemu-system-x86_64 -enable-kvm -cpu SandyBridge -smp 2 -m 16G

(please refer to attached dmesg/kmsg for entire log/backtrace)


+-----------------------------------------------------+------------+------------+
| | a51749ab34 | 4f37585fa0 |
+-----------------------------------------------------+------------+------------+
| WARNING:at_kernel/locking/lockdep.c:#__lock_acquire | 0 | 6 |
| EIP:__lock_acquire | 0 | 6 |
+-----------------------------------------------------+------------+------------+


If you fix the issue in a separate patch/commit (i.e. not just a new version of
the same patch/commit), kindly add following tags
| Reported-by: kernel test robot <oliver.sang@xxxxxxxxx>
| Closes: https://lore.kernel.org/oe-lkp/202312221708.b143534-oliver.sang@xxxxxxxxx


[ 9.777113][ T10] ------------[ cut here ]------------
[ 9.777784][ T10] DEBUG_LOCKS_WARN_ON(hlock->references < references)
[ 9.777795][ T10] WARNING: CPU: 0 PID: 10 at kernel/locking/lockdep.c:5055 __lock_acquire (kernel/locking/lockdep.c:5055 (discriminator 9))
[ 9.778839][ T10] Modules linked in:
[ 9.778839][ T10] CPU: 0 PID: 10 Comm: kworker/u2:0 Not tainted 6.7.0-rc1-00006-g4f37585fa02f #5
[ 9.778839][ T10] Workqueue: test-ww_mutex stress_inorder_work
[ 9.778839][ T10] EIP: __lock_acquire (kernel/locking/lockdep.c:5055 (discriminator 9))
[ 9.778839][ T10] Code: e8 ae 10 2e 00 85 c0 0f 84 0e 0f 00 00 8b 1d 94 9c b5 ce 85 db 0f 85 00 0f 00 00 68 64 16 34 ce 68 fe 17 33 ce e8 09 22 fc ff <0f> 0b 58 5a e9 28 12 00 00 a1 90 ef 24 cf 85 c0 74 07 eb 2a 8d 74
All code
========
0: e8 ae 10 2e 00 callq 0x2e10b3
5: 85 c0 test %eax,%eax
7: 0f 84 0e 0f 00 00 je 0xf1b
d: 8b 1d 94 9c b5 ce mov -0x314a636c(%rip),%ebx # 0xffffffffceb59ca7
13: 85 db test %ebx,%ebx
15: 0f 85 00 0f 00 00 jne 0xf1b
1b: 68 64 16 34 ce pushq $0xffffffffce341664
20: 68 fe 17 33 ce pushq $0xffffffffce3317fe
25: e8 09 22 fc ff callq 0xfffffffffffc2233
2a:* 0f 0b ud2 <-- trapping instruction
2c: 58 pop %rax
2d: 5a pop %rdx
2e: e9 28 12 00 00 jmpq 0x125b
33: a1 90 ef 24 cf 85 c0 movabs 0x774c085cf24ef90,%eax
3a: 74 07
3c: eb 2a jmp 0x68
3e: 8d .byte 0x8d
3f: 74 .byte 0x74

Code starting with the faulting instruction
===========================================
0: 0f 0b ud2
2: 58 pop %rax
3: 5a pop %rdx
4: e9 28 12 00 00 jmpq 0x1231
9: a1 90 ef 24 cf 85 c0 movabs 0x774c085cf24ef90,%eax
10: 74 07
12: eb 2a jmp 0x3e
14: 8d .byte 0x8d
15: 74 .byte 0x74
[ 9.778839][ T10] EAX: 00000033 EBX: 00000000 ECX: c0245cb4 EDX: ce9da1ac
[ 9.778839][ T10] ESI: c26cb37c EDI: c02569ac EBP: c0245db0 ESP: c0245d60
[ 9.778839][ T10] DS: 007b ES: 007b FS: 0000 GS: 0000 SS: 0068 EFLAGS: 00010002
[ 9.778839][ T10] CR0: 80050033 CR2: ffdda000 CR3: 0ec21000 CR4: 00040690
[ 9.778839][ T10] DR0: 00000000 DR1: 00000000 DR2: 00000000 DR3: 00000000
[ 9.778839][ T10] DR6: fffe0ff0 DR7: 00000400
[ 9.778839][ T10] Call Trace:
[ 9.778839][ T10] ? show_regs (arch/x86/kernel/dumpstack.c:478)
[ 9.778839][ T10] ? __warn (kernel/panic.c:677)
[ 9.778839][ T10] ? __lock_acquire (kernel/locking/lockdep.c:5055 (discriminator 9))
[ 9.778839][ T10] ? report_bug (lib/bug.c:201 lib/bug.c:219)
[ 9.778839][ T10] ? exc_overflow (arch/x86/kernel/traps.c:250)
[ 9.778839][ T10] ? handle_bug (arch/x86/kernel/traps.c:237)
[ 9.778839][ T10] ? exc_invalid_op (arch/x86/kernel/traps.c:258 (discriminator 1))
[ 9.778839][ T10] ? handle_exception (arch/x86/entry/entry_32.S:1056)
[ 9.778839][ T10] ? __lock_acquire (kernel/locking/lockdep.c:5047)
[ 9.778839][ T10] ? exc_overflow (arch/x86/kernel/traps.c:250)
[ 9.778839][ T10] ? __lock_acquire (kernel/locking/lockdep.c:5055 (discriminator 9))
[ 9.778839][ T10] ? exc_overflow (arch/x86/kernel/traps.c:250)
[ 9.778839][ T10] ? __lock_acquire (kernel/locking/lockdep.c:5055 (discriminator 9))
[ 9.778839][ T10] ? kvm_sched_clock_read (arch/x86/kernel/kvmclock.c:91)
[ 9.778839][ T10] lock_acquire (kernel/locking/lockdep.c:467 kernel/locking/lockdep.c:5755)
[ 9.778839][ T10] ? stress_inorder_work (kernel/locking/test-ww_mutex.c:457)
[ 9.778839][ T10] ? lock_is_held_type (kernel/locking/lockdep.c:5494 kernel/locking/lockdep.c:5824)
[ 9.778839][ T10] __ww_mutex_lock+0xb1/0xd84
[ 9.778839][ T10] ? stress_inorder_work (kernel/locking/test-ww_mutex.c:457)
[ 9.778839][ T10] ww_mutex_lock (kernel/locking/mutex.c:878)
[ 9.778839][ T10] stress_inorder_work (kernel/locking/test-ww_mutex.c:457)
[ 9.778839][ T10] process_scheduled_works (kernel/workqueue.c:2630 include/linux/jump_label.h:207 include/trace/events/workqueue.h:108 kernel/workqueue.c:2635 kernel/workqueue.c:2703)
[ 9.778839][ T10] worker_thread (include/linux/list.h:373 kernel/workqueue.c:841 kernel/workqueue.c:2785)
[ 9.778839][ T10] kthread (kernel/kthread.c:390)
[ 9.778839][ T10] ? rescuer_thread (kernel/workqueue.c:2730)
[ 9.778839][ T10] ? kthread_complete_and_exit (kernel/kthread.c:341)
[ 9.778839][ T10] ret_from_fork (arch/x86/kernel/process.c:153)
[ 9.778839][ T10] ? kthread_complete_and_exit (kernel/kthread.c:341)
[ 9.778839][ T10] ret_from_fork_asm (arch/x86/entry/entry_32.S:741)
[ 9.778839][ T10] entry_INT80_32 (arch/x86/entry/entry_32.S:947)
[ 9.778839][ T10] irq event stamp: 14037
[ 9.778839][ T10] hardirqs last enabled at (14037): irqentry_exit (kernel/entry/common.c:435)
[ 9.778839][ T10] hardirqs last disabled at (14036): common_interrupt (arch/x86/kernel/irq.c:247)
[ 9.778839][ T10] softirqs last enabled at (8978): __do_softirq (arch/x86/include/asm/preempt.h:27 kernel/softirq.c:400 kernel/softirq.c:582)
[ 9.778839][ T10] softirqs last disabled at (8969): do_softirq_own_stack (arch/x86/kernel/irq_32.c:57 arch/x86/kernel/irq_32.c:147)
[ 9.778839][ T10] ---[ end trace 0000000000000000 ]---
[ 9.917906][ T36] torture_spin_lock_write_delay: delay = 25 jiffies.
[ 10.273181][ T36] torture_spin_lock_write_delay: delay = 25 jiffies.
[ 10.621916][ T36] torture_spin_lock_write_delay: delay = 25 jiffies.
[ 10.788923][ T36] torture_spin_lock_write_delay: delay = 25 jiffies.
[ 10.919665][ T36] torture_spin_lock_write_delay: delay = 26 jiffies.
[ 11.085916][ T36] torture_spin_lock_write_delay: delay = 25 jiffies.
[ 11.471931][ T35] torture_spin_lock_write_delay: delay = 25 jiffies.
[ 11.784602][ T1] All ww mutex selftests passed



The kernel config and materials to reproduce are available at:
https://download.01.org/0day-ci/archive/20231222/202312221708.b143534-oliver.sang@xxxxxxxxx



--
0-DAY CI Kernel Test Service
https://github.com/intel/lkp-tests/wiki