Re: [PATCH] Remove extra unlock for the mutex
From: kernel test robot
Date: Mon Oct 16 2023 - 10:09:15 EST
Hello,
kernel test robot noticed "INFO:rcu_sched_self-detected_stall_on_CPU" on:
commit: f0b98c2f83318c5b0668d160244c97a4c9b4f823 ("[PATCH] Remove extra unlock for the mutex")
url: https://github.com/intel-lab-lkp/linux/commits/Abhinav-Singh/Remove-extra-unlock-for-the-mutex/20231011-064851
base: https://git.kernel.org/cgit/linux/kernel/git/torvalds/linux.git 1c8b86a3799f7e5be903c3f49fcdaee29fd385b5
patch link: https://lore.kernel.org/all/20231010224630.238254-1-singhabhinav9051571833@xxxxxxxxx/
patch subject: [PATCH] Remove extra unlock for the mutex
in testcase: boot
compiler: gcc-12
test machine: qemu-system-x86_64 -enable-kvm -cpu SandyBridge -smp 2 -m 16G
(please refer to attached dmesg/kmsg for entire log/backtrace)
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/202310162034.6677994c-oliver.sang@xxxxxxxxx
[ 340.173373][ C0] rcu: INFO: rcu_sched self-detected stall on CPU
[ 340.174586][ C0] rcu: 0-....: (1 GPs behind) idle=03dc/1/0x4000000000000000 softirq=3450/3451 fqs=24649
[ 340.175977][ C0] rcu: (t=100002 jiffies g=3977 q=51 ncpus=2)
[ 340.176937][ C0] CPU: 0 PID: 84 Comm: (sd-listen) Not tainted 6.6.0-rc5-00056-gf0b98c2f8331 #1
[ 340.178240][ C0] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 1.16.2-debian-1.16.2-1 04/01/2014
[ 340.179747][ C0] RIP: 0010:native_queued_spin_lock_slowpath (arch/x86/include/asm/vdso/processor.h:19 arch/x86/include/asm/qspinlock.h:99 kernel/locking/qspinlock.c:327)
[ 340.180789][ C0] Code: 55 41 54 55 53 48 89 fb 66 90 ba 01 00 00 00 8b 03 85 c0 75 13 f0 0f b1 13 85 c0 75 f2 5b 5d 41 5c 41 5d c3 cc cc cc cc f3 90 <eb> e3 81 fe 00 01 00 00 74 4a 81 fe ff 00 00 00 77 77 f0 0f ba 2b
All code
========
0: 55 push %rbp
1: 41 54 push %r12
3: 55 push %rbp
4: 53 push %rbx
5: 48 89 fb mov %rdi,%rbx
8: 66 90 xchg %ax,%ax
a: ba 01 00 00 00 mov $0x1,%edx
f: 8b 03 mov (%rbx),%eax
11: 85 c0 test %eax,%eax
13: 75 13 jne 0x28
15: f0 0f b1 13 lock cmpxchg %edx,(%rbx)
19: 85 c0 test %eax,%eax
1b: 75 f2 jne 0xf
1d: 5b pop %rbx
1e: 5d pop %rbp
1f: 41 5c pop %r12
21: 41 5d pop %r13
23: c3 retq
24: cc int3
25: cc int3
26: cc int3
27: cc int3
28: f3 90 pause
2a:* eb e3 jmp 0xf <-- trapping instruction
2c: 81 fe 00 01 00 00 cmp $0x100,%esi
32: 74 4a je 0x7e
34: 81 fe ff 00 00 00 cmp $0xff,%esi
3a: 77 77 ja 0xb3
3c: f0 lock
3d: 0f .byte 0xf
3e: ba .byte 0xba
3f: 2b .byte 0x2b
Code starting with the faulting instruction
===========================================
0: eb e3 jmp 0xffffffffffffffe5
2: 81 fe 00 01 00 00 cmp $0x100,%esi
8: 74 4a je 0x54
a: 81 fe ff 00 00 00 cmp $0xff,%esi
10: 77 77 ja 0x89
12: f0 lock
13: 0f .byte 0xf
14: ba .byte 0xba
15: 2b .byte 0x2b
[ 340.183349][ C0] RSP: 0018:ffffb338c047fdc8 EFLAGS: 00000202
[ 340.184239][ C0] RAX: 0000000000000001 RBX: ffff9f0300e68d60 RCX: ffff9f03003b6bf8
[ 340.185380][ C0] RDX: 0000000000000001 RSI: 0000000000000001 RDI: ffff9f0300e68d60
[ 340.186574][ C0] RBP: 000000000000006f R08: 0000000000000000 R09: 0000000000000000
[ 340.187764][ C0] R10: 0000000000000000 R11: 0000000000000000 R12: ffffffff86d34d40
[ 340.188949][ C0] R13: 0000000000000000 R14: ffffffff86d37a80 R15: ffff9f0300e68d60
[ 340.190188][ C0] FS: 00007f34324f1900(0000) GS:ffff9f062fc00000(0000) knlGS:0000000000000000
[ 340.191487][ C0] CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[ 340.192453][ C0] CR2: 000055e1849fc3fc CR3: 0000000100856000 CR4: 00000000000406f0
[ 340.193640][ C0] DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
[ 340.194791][ C0] DR3: 0000000000000000 DR6: 00000000fffe0ff0 DR7: 0000000000000400
[ 340.195997][ C0] Call Trace:
[ 340.196616][ C0] <IRQ>
[ 340.197133][ C0] ? rcu_dump_cpu_stacks (kernel/rcu/tree_stall.h:372)
[ 340.197953][ C0] ? print_cpu_stall (kernel/rcu/tree_stall.h:692)
[ 340.198677][ C0] ? check_cpu_stall (kernel/rcu/tree_stall.h:775)
[ 340.199433][ C0] ? rcu_pending (kernel/rcu/tree_nocb.h:1018 kernel/rcu/tree.c:3865)
[ 340.200129][ C0] ? rcu_sched_clock_irq (kernel/rcu/tree.c:2240)
[ 340.200928][ C0] ? update_process_times (arch/x86/include/asm/preempt.h:27 kernel/time/timer.c:2073)
[ 340.201731][ C0] ? tick_sched_handle (kernel/time/tick-sched.c:255)
[ 340.202471][ C0] ? tick_sched_timer (kernel/time/tick-sched.c:1497)
[ 340.203215][ C0] ? __pfx_tick_sched_timer (kernel/time/tick-sched.c:1479)
[ 340.204056][ C0] ? __hrtimer_run_queues (kernel/time/hrtimer.c:1688 kernel/time/hrtimer.c:1752)
[ 340.204889][ C0] ? hrtimer_interrupt (kernel/time/hrtimer.c:1817)
[ 340.205654][ C0] ? __sysvec_apic_timer_interrupt (arch/x86/include/asm/jump_label.h:27 include/linux/jump_label.h:207 arch/x86/include/asm/trace/irq_vectors.h:41 arch/x86/kernel/apic/apic.c:1081)
[ 340.206540][ C0] ? sysvec_apic_timer_interrupt (arch/x86/kernel/apic/apic.c:1074 (discriminator 14))
[ 340.207374][ C0] </IRQ>
[ 340.207877][ C0] <TASK>
[ 340.208388][ C0] ? asm_sysvec_apic_timer_interrupt (arch/x86/include/asm/idtentry.h:645)
[ 340.209329][ C0] ? native_queued_spin_lock_slowpath (arch/x86/include/asm/vdso/processor.h:19 arch/x86/include/asm/qspinlock.h:99 kernel/locking/qspinlock.c:327)
[ 340.210253][ C0] _raw_spin_lock_bh (arch/x86/include/asm/paravirt.h:586 arch/x86/include/asm/qspinlock.h:51 include/asm-generic/qspinlock.h:114 include/linux/spinlock.h:187 include/linux/spinlock_api_smp.h:127 kernel/locking/spinlock.c:178)
[ 340.210996][ C0] inet_csk_get_port (net/ipv4/inet_connection_sock.c:536)
[ 340.211757][ C0] inet_csk_listen_start (net/ipv4/inet_connection_sock.c:1255)
[ 340.212570][ C0] __inet_listen_sk (net/ipv4/af_inet.c:218)
[ 340.213320][ C0] ? __cond_resched (kernel/sched/core.c:8581)
[ 340.214041][ C0] ? aa_sk_perm (security/apparmor/include/cred.h:153 security/apparmor/net.c:176)
[ 340.214778][ C0] ? __cond_resched (kernel/sched/core.c:8581)
[ 340.215488][ C0] ? lock_sock_nested (net/core/sock.c:3509)
[ 340.216234][ C0] inet_listen (net/ipv4/af_inet.c:239)
[ 340.216950][ C0] __sys_listen (include/linux/file.h:32 net/socket.c:1885)
[ 340.217686][ C0] __x64_sys_listen (net/socket.c:1892 net/socket.c:1890 net/socket.c:1890)
[ 340.218414][ C0] do_syscall_64 (arch/x86/entry/common.c:50 arch/x86/entry/common.c:80)
[ 340.219135][ C0] entry_SYSCALL_64_after_hwframe (arch/x86/entry/entry_64.S:120)
[ 340.220005][ C0] RIP: 0033:0x7f3432ccefa7
[ 340.220771][ C0] Code: f0 ff ff 73 01 c3 48 8b 0d e6 ee 0b 00 f7 d8 64 89 01 48 83 c8 ff c3 66 2e 0f 1f 84 00 00 00 00 00 66 90 b8 32 00 00 00 0f 05 <48> 3d 01 f0 ff ff 73 01 c3 48 8b 0d b9 ee 0b 00 f7 d8 64 89 01 48
All code
========
0: f0 ff lock (bad)
2: ff 73 01 pushq 0x1(%rbx)
5: c3 retq
6: 48 8b 0d e6 ee 0b 00 mov 0xbeee6(%rip),%rcx # 0xbeef3
d: f7 d8 neg %eax
f: 64 89 01 mov %eax,%fs:(%rcx)
12: 48 83 c8 ff or $0xffffffffffffffff,%rax
16: c3 retq
17: 66 2e 0f 1f 84 00 00 nopw %cs:0x0(%rax,%rax,1)
1e: 00 00 00
21: 66 90 xchg %ax,%ax
23: b8 32 00 00 00 mov $0x32,%eax
28: 0f 05 syscall
2a:* 48 3d 01 f0 ff ff cmp $0xfffffffffffff001,%rax <-- trapping instruction
30: 73 01 jae 0x33
32: c3 retq
33: 48 8b 0d b9 ee 0b 00 mov 0xbeeb9(%rip),%rcx # 0xbeef3
3a: f7 d8 neg %eax
3c: 64 89 01 mov %eax,%fs:(%rcx)
3f: 48 rex.W
Code starting with the faulting instruction
===========================================
0: 48 3d 01 f0 ff ff cmp $0xfffffffffffff001,%rax
6: 73 01 jae 0x9
8: c3 retq
9: 48 8b 0d b9 ee 0b 00 mov 0xbeeb9(%rip),%rcx # 0xbeec9
10: f7 d8 neg %eax
12: 64 89 01 mov %eax,%fs:(%rcx)
15: 48 rex.W
The kernel config and materials to reproduce are available at:
https://download.01.org/0day-ci/archive/20231016/202310162034.6677994c-oliver.sang@xxxxxxxxx
--
0-DAY CI Kernel Test Service
https://github.com/intel/lkp-tests/wiki