Following kernel crash noticed while running perf testing on qemu-x86_64 with stable-rc 6.3.4-rc2 + kselftest merge configs.
Reported-by: Linux Kernel Functional Testing lkft@linaro.org
logs: ===== INFO: Performing perf record test...
Parse sched tracepoints fields: Ok 16: syscalls:sys_enter_openat event fields : --- start --- test child forked, pid 255 <4>[ 152.221288] int3: 0000 [#1] PREEMPT SMP PTI <4>[ 152.221564] CPU: 0 PID: 255 Comm: perf Not tainted 6.3.4-rc2 #1 <4>[ 152.221607] Hardware name: QEMU Standard PC (Q35 + ICH9, 2009), BIOS 1.14.0-2 04/01/2014 <4>[ 152.221733] RIP: 0010:__schedule+0x29e/0xaa0 <4>[ 152.222066] Code: 00 48 29 c1 49 01 8e 48 04 00 00 48 85 db 74 0f 48 01 8b 90 0c 00 00 48 83 83 88 0c 00 00 01 0f 1f 44 00 00 0f 1f 44 00 00 e9 <7a> 01 00 00 49 0f ba ac 24 18 0a 00 00 00 49 83 bc 24 08 0a 00 00 <4>[ 152.222122] RSP: 0018:ffff94aec0677bc0 EFLAGS: 00000046 <4>[ 152.222170] RAX: ffffffffa2e10900 RBX: ffff8b517bc2b700 RCX: 0000000000000004 <4>[ 152.222184] RDX: 00000023711138c0 RSI: 0000000000000000 RDI: ffff8b517bc2b700 <4>[ 152.222197] RBP: ffff94aec0677c28 R08: ffff8b5102aa6a00 R09: 000000000000004e <4>[ 152.222211] R10: 0000000000000001 R11: 0000000000000001 R12: ffff8b51009e3c00 <4>[ 152.222223] R13: ffffffffa2cf3f48 R14: ffffffffa2e10900 R15: ffff8b51009e4248 <4>[ 152.222275] FS: 00007f6b8ea81800(0000) GS:ffff8b517bc00000(0000) knlGS:0000000000000000 <4>[ 152.222294] CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033 <4>[ 152.222308] CR2: 00007f6b8dd204e0 CR3: 0000000105a1c000 CR4: 00000000000006f0 <4>[ 152.222409] Call Trace: <4>[ 152.222500] <TASK> <4>[ 152.222605] schedule+0x6a/0xf0 <4>[ 152.222664] schedule_timeout+0x14f/0x160 <4>[ 152.222680] wait_for_completion+0x8c/0x140 <4>[ 152.222696] __wait_rcu_gp+0x13e/0x140 <4>[ 152.222712] synchronize_rcu+0x12f/0x140 <4>[ 152.222731] ? __pfx_call_rcu_hurry+0x10/0x10 <4>[ 152.222748] ? __pfx_wakeme_after_rcu+0x10/0x10 <4>[ 152.222766] perf_event_alloc+0xd53/0xdc0 <4>[ 152.222783] ? preempt_count_sub+0x50/0x80 <4>[ 152.222795] ? _raw_spin_unlock+0x1a/0x40 <4>[ 152.222810] __do_sys_perf_event_open+0x1df/0xd10 <4>[ 152.222838] __x64_sys_perf_event_open+0x26/0x30 <4>[ 152.222849] do_syscall_64+0x3e/0x90 <4>[ 152.222863] entry_SYSCALL_64_after_hwframe+0x72/0xdc <4>[ 152.222920] RIP: 0033:0x7f6b8dd204f9 <4>[ 152.223150] Code: 08 89 e8 5b 5d c3 66 2e 0f 1f 84 00 00 00 00 00 90 48 89 f8 48 89 f7 48 89 d6 48 89 ca 4d 89 c2 4d 89 c8 4c 8b 4c 24 08 0f 05 <48> 3d 01 f0 ff ff 73 01 c3 48 8b 0d d7 08 0d 00 f7 d8 64 89 01 48 <4>[ 152.223158] RSP: 002b:00007ffd51880f68 EFLAGS: 00000202 ORIG_RAX: 000000000000012a <4>[ 152.223175] RAX: ffffffffffffffda RBX: 00000000ffffffff RCX: 00007f6b8dd204f9 <4>[ 152.223181] RDX: 0000000000000000 RSI: 00000000000000ff RDI: 000055e658912b50 <4>[ 152.223187] RBP: 00007ffd51881030 R08: 0000000000000008 R09: 00007ffd51881090 <4>[ 152.223192] R10: 00000000ffffffff R11: 0000000000000202 R12: 0000000000000008 <4>[ 152.223198] R13: 0000000000000000 R14: 0000000000000000 R15: 000055e658912b40 <4>[ 152.223246] </TASK> <4>[ 152.223308] Modules linked in: <4>[ 152.247884] ---[ end trace 0000000000000000 ]--- <4>[ 152.248004] RIP: 0010:__schedule+0x29e/0xaa0 <4>[ 152.248051] Code: 00 48 29 c1 49 01 8e 48 04 00 00 48 85 db 74 0f 48 01 8b 90 0c 00 00 48 83 83 88 0c 00 00 01 0f 1f 44 00 00 0f 1f 44 00 00 e9 <7a> 01 00 00 49 0f ba ac 24 18 0a 00 00 00 49 83 bc 24 08 0a 00 00 <4>[ 152.248066] RSP: 0018:ffff94aec0677bc0 EFLAGS: 00000046 <4>[ 152.248089] RAX: ffffffffa2e10900 RBX: ffff8b517bc2b700 RCX: 0000000000000004 <4>[ 152.248099] RDX: 00000023711138c0 RSI: 0000000000000000 RDI: ffff8b517bc2b700 <4>[ 152.248269] RBP: ffff94aec0677c28 R08: ffff8b5102aa6a00 R09: 000000000000004e <4>[ 152.248282] R10: 0000000000000001 R11: 0000000000000001 R12: ffff8b51009e3c00 <4>[ 152.248294] R13: ffffffffa2cf3f48 R14: ffffffffa2e10900 R15: ffff8b51009e4248 <4>[ 152.248304] FS: 00007f6b8ea81800(0000) GS:ffff8b517bc00000(0000) knlGS:0000000000000000 <4>[ 152.248316] CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033 <4>[ 152.248479] CR2: 00007f6b8dd204e0 CR3: 0000000105a1c000 CR4: 00000000000006f0 <0>[ 152.248663] Kernel panic - not syncing: Fatal exception in interrupt <4>[ 152.248980] int3: 0000 [#2] PREEMPT SMP PTI <4>[ 152.249101] CPU: 1 PID: 32 Comm: kworker/u4:3 Tainted: G D 6.3.4-rc2 #1 <4>[ 152.249124] Hardware name: QEMU Standard PC (Q35 + ICH9, 2009), BIOS 1.14.0-2 04/01/2014 <4>[ 152.249292] Workqueue: 0x0 (events_unbound) <4>[ 152.249420] RIP: 0010:__schedule+0x29e/0xaa0 <4>[ 152.249471] Code: 00 48 29 c1 49 01 8e 48 04 00 00 48 85 db 74 0f 48 01 8b 90 0c 00 00 48 83 83 88 0c 00 00 01 0f 1f 44 00 00 0f 1f 44 00 00 e9 <7a> 01 00 00 49 0f ba ac 24 18 0a 00 00 00 49 83 bc 24 08 0a 00 00 <4>[ 152.249486] RSP: 0018:ffff94aec0117e38 EFLAGS: 00000046 <4>[ 152.249502] RAX: ffff8b51002d8000 RBX: ffff8b517bd2b700 RCX: 0000000000000004 <4>[ 152.249512] RDX: 0000002372bd853f RSI: ffffffffffa7caff RDI: ffff8b517bd2b700 <4>[ 152.249522] RBP: ffff94aec0117ea0 R08: 0000000000000400 R09: 0000000000000361 <4>[ 152.249532] R10: 0000000000000001 R11: 0000000000000000 R12: ffff8b51008a0f00 <4>[ 152.249542] R13: ffffffffa2cf3f48 R14: ffff8b51002d8000 R15: ffff8b51008a1548 <4>[ 152.249552] FS: 0000000000000000(0000) GS:ffff8b517bd00000(0000) knlGS:0000000000000000 <4>[ 152.249565] CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033 <4>[ 152.249576] CR2: 00007ffd518816b8 CR3: 000000010591e000 CR4: 00000000000006e0 <4>[ 152.249588] Call Trace: <4>[ 152.249603] <TASK> <4>[ 152.249636] schedule+0x6a/0xf0 <4>[ 152.249658] worker_thread+0xc0/0x3e0 <4>[ 152.249684] ? __pfx_worker_thread+0x10/0x10 <4>[ 152.249704] kthread+0xfc/0x120 <4>[ 152.249721] ? __pfx_kthread+0x10/0x10 <4>[ 152.249739] ret_from_fork+0x2c/0x50 <4>[ 152.249797] </TASK> <4>[ 152.249805] Modules linked in: <4>[ 152.250386] ---[ end trace 0000000000000000 ]--- <4>[ 152.250399] RIP: 0010:__schedule+0x29e/0xaa0 <4>[ 152.250421] Code: 00 48 29 c1 49 01 8e 48 04 00 00 48 85 db 74 0f 48 01 8b 90 0c 00 00 48 83 83 88 0c 00 00 01 0f 1f 44 00 00 0f 1f 44 00 00 e9 <7a> 01 00 00 49 0f ba ac 24 18 0a 00 00 00 49 83 bc 24 08 0a 00 00 <4>[ 152.250434] RSP: 0018:ffff94aec0677bc0 EFLAGS: 00000046 <4>[ 152.250448] RAX: ffffffffa2e10900 RBX: ffff8b517bc2b700 RCX: 0000000000000004 <4>[ 152.250458] RDX: 00000023711138c0 RSI: 0000000000000000 RDI: ffff8b517bc2b700 <4>[ 152.250467] RBP: ffff94aec0677c28 R08: ffff8b5102aa6a00 R09: 000000000000004e <4>[ 152.250477] R10: 0000000000000001 R11: 0000000000000001 R12: ffff8b51009e3c00 <4>[ 152.250486] R13: ffffffffa2cf3f48 R14: ffffffffa2e10900 R15: ffff8b51009e4248 <4>[ 152.250496] FS: 0000000000000000(0000) GS:ffff8b517bd00000(0000) knlGS:0000000000000000 <4>[ 152.250508] CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033 <4>[ 152.250519] CR2: 00007ffd518816b8 CR3: 000000010591e000 CR4: 00000000000006e0 <0>[ 154.015533] Shutting down cpus with NMI <0>[ 154.016784] Kernel Offset: 0x20000000 from 0xffffffff81000000 (relocation range: 0xffffffff80000000-0xffffffffbfffffff)
log links, ===== - https://qa-reports.linaro.org/lkft/linux-stable-rc-linux-6.3.y/build/v6.3.3-... - https://qa-reports.linaro.org/lkft/linux-stable-rc-linux-6.3.y/build/v6.3.3-... - https://storage.tuxsuite.com/public/linaro/lkft/builds/2QCeuajqUTZlyC4kEyQGx... - https://storage.tuxsuite.com/public/linaro/lkft/builds/2QCeuajqUTZlyC4kEyQGx...
-- Linaro LKFT https://lkft.linaro.org
Hello Naresh,
On Wed, May 24, 2023 at 5:02 AM Naresh Kamboju naresh.kamboju@linaro.org wrote:
Following kernel crash noticed while running perf testing on qemu-x86_64 with stable-rc 6.3.4-rc2 + kselftest merge configs.
Reported-by: Linux Kernel Functional Testing lkft@linaro.org
logs:
INFO: Performing perf record test...
Parse sched tracepoints fields: Ok 16: syscalls:sys_enter_openat event fields : --- start --- test child forked, pid 255 <4>[ 152.221288] int3: 0000 [#1] PREEMPT SMP PTI <4>[ 152.221564] CPU: 0 PID: 255 Comm: perf Not tainted 6.3.4-rc2 #1 <4>[ 152.221607] Hardware name: QEMU Standard PC (Q35 + ICH9, 2009), BIOS 1.14.0-2 04/01/2014 <4>[ 152.221733] RIP: 0010:__schedule+0x29e/0xaa0 <4>[ 152.222066] Code: 00 48 29 c1 49 01 8e 48 04 00 00 48 85 db 74 0f 48 01 8b 90 0c 00 00 48 83 83 88 0c 00 00 01 0f 1f 44 00 00 0f 1f 44 00 00 e9 <7a> 01 00 00 49 0f ba ac 24 18 0a 00 00 00 49 83 bc 24 08 0a 00 00 <4>[ 152.222122] RSP: 0018:ffff94aec0677bc0 EFLAGS: 00000046 <4>[ 152.222170] RAX: ffffffffa2e10900 RBX: ffff8b517bc2b700 RCX: 0000000000000004 <4>[ 152.222184] RDX: 00000023711138c0 RSI: 0000000000000000 RDI: ffff8b517bc2b700 <4>[ 152.222197] RBP: ffff94aec0677c28 R08: ffff8b5102aa6a00 R09: 000000000000004e <4>[ 152.222211] R10: 0000000000000001 R11: 0000000000000001 R12: ffff8b51009e3c00 <4>[ 152.222223] R13: ffffffffa2cf3f48 R14: ffffffffa2e10900 R15: ffff8b51009e4248 <4>[ 152.222275] FS: 00007f6b8ea81800(0000) GS:ffff8b517bc00000(0000) knlGS:0000000000000000 <4>[ 152.222294] CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033 <4>[ 152.222308] CR2: 00007f6b8dd204e0 CR3: 0000000105a1c000 CR4: 00000000000006f0 <4>[ 152.222409] Call Trace: <4>[ 152.222500] <TASK> <4>[ 152.222605] schedule+0x6a/0xf0 <4>[ 152.222664] schedule_timeout+0x14f/0x160 <4>[ 152.222680] wait_for_completion+0x8c/0x140 <4>[ 152.222696] __wait_rcu_gp+0x13e/0x140 <4>[ 152.222712] synchronize_rcu+0x12f/0x140 <4>[ 152.222731] ? __pfx_call_rcu_hurry+0x10/0x10 <4>[ 152.222748] ? __pfx_wakeme_after_rcu+0x10/0x10 <4>[ 152.222766] perf_event_alloc+0xd53/0xdc0 <4>[ 152.222783] ? preempt_count_sub+0x50/0x80 <4>[ 152.222795] ? _raw_spin_unlock+0x1a/0x40 <4>[ 152.222810] __do_sys_perf_event_open+0x1df/0xd10 <4>[ 152.222838] __x64_sys_perf_event_open+0x26/0x30 <4>[ 152.222849] do_syscall_64+0x3e/0x90 <4>[ 152.222863] entry_SYSCALL_64_after_hwframe+0x72/0xdc <4>[ 152.222920] RIP: 0033:0x7f6b8dd204f9 <4>[ 152.223150] Code: 08 89 e8 5b 5d c3 66 2e 0f 1f 84 00 00 00 00 00 90 48 89 f8 48 89 f7 48 89 d6 48 89 ca 4d 89 c2 4d 89 c8 4c 8b 4c 24 08 0f 05 <48> 3d 01 f0 ff ff 73 01 c3 48 8b 0d d7 08 0d 00 f7 d8 64 89 01 48 <4>[ 152.223158] RSP: 002b:00007ffd51880f68 EFLAGS: 00000202 ORIG_RAX: 000000000000012a <4>[ 152.223175] RAX: ffffffffffffffda RBX: 00000000ffffffff RCX: 00007f6b8dd204f9 <4>[ 152.223181] RDX: 0000000000000000 RSI: 00000000000000ff RDI: 000055e658912b50 <4>[ 152.223187] RBP: 00007ffd51881030 R08: 0000000000000008 R09: 00007ffd51881090 <4>[ 152.223192] R10: 00000000ffffffff R11: 0000000000000202 R12: 0000000000000008 <4>[ 152.223198] R13: 0000000000000000 R14: 0000000000000000 R15: 000055e658912b40 <4>[ 152.223246] </TASK> <4>[ 152.223308] Modules linked in: <4>[ 152.247884] ---[ end trace 0000000000000000 ]--- <4>[ 152.248004] RIP: 0010:__schedule+0x29e/0xaa0 <4>[ 152.248051] Code: 00 48 29 c1 49 01 8e 48 04 00 00 48 85 db 74 0f 48 01 8b 90 0c 00 00 48 83 83 88 0c 00 00 01 0f 1f 44 00 00 0f 1f 44 00 00 e9 <7a> 01 00 00 49 0f ba ac 24 18 0a 00 00 00 49 83 bc 24 08 0a 00 00 <4>[ 152.248066] RSP: 0018:ffff94aec0677bc0 EFLAGS: 00000046 <4>[ 152.248089] RAX: ffffffffa2e10900 RBX: ffff8b517bc2b700 RCX: 0000000000000004 <4>[ 152.248099] RDX: 00000023711138c0 RSI: 0000000000000000 RDI: ffff8b517bc2b700 <4>[ 152.248269] RBP: ffff94aec0677c28 R08: ffff8b5102aa6a00 R09: 000000000000004e <4>[ 152.248282] R10: 0000000000000001 R11: 0000000000000001 R12: ffff8b51009e3c00 <4>[ 152.248294] R13: ffffffffa2cf3f48 R14: ffffffffa2e10900 R15: ffff8b51009e4248 <4>[ 152.248304] FS: 00007f6b8ea81800(0000) GS:ffff8b517bc00000(0000) knlGS:0000000000000000 <4>[ 152.248316] CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033 <4>[ 152.248479] CR2: 00007f6b8dd204e0 CR3: 0000000105a1c000 CR4: 00000000000006f0 <0>[ 152.248663] Kernel panic - not syncing: Fatal exception in interrupt <4>[ 152.248980] int3: 0000 [#2] PREEMPT SMP PTI <4>[ 152.249101] CPU: 1 PID: 32 Comm: kworker/u4:3 Tainted: G D 6.3.4-rc2 #1 <4>[ 152.249124] Hardware name: QEMU Standard PC (Q35 + ICH9, 2009), BIOS 1.14.0-2 04/01/2014 <4>[ 152.249292] Workqueue: 0x0 (events_unbound) <4>[ 152.249420] RIP: 0010:__schedule+0x29e/0xaa0 <4>[ 152.249471] Code: 00 48 29 c1 49 01 8e 48 04 00 00 48 85 db 74 0f 48 01 8b 90 0c 00 00 48 83 83 88 0c 00 00 01 0f 1f 44 00 00 0f 1f 44 00 00 e9 <7a> 01 00 00 49 0f ba ac 24 18 0a 00 00 00 49 83 bc 24 08 0a 00 00 <4>[ 152.249486] RSP: 0018:ffff94aec0117e38 EFLAGS: 00000046 <4>[ 152.249502] RAX: ffff8b51002d8000 RBX: ffff8b517bd2b700 RCX: 0000000000000004 <4>[ 152.249512] RDX: 0000002372bd853f RSI: ffffffffffa7caff RDI: ffff8b517bd2b700 <4>[ 152.249522] RBP: ffff94aec0117ea0 R08: 0000000000000400 R09: 0000000000000361 <4>[ 152.249532] R10: 0000000000000001 R11: 0000000000000000 R12: ffff8b51008a0f00 <4>[ 152.249542] R13: ffffffffa2cf3f48 R14: ffff8b51002d8000 R15: ffff8b51008a1548 <4>[ 152.249552] FS: 0000000000000000(0000) GS:ffff8b517bd00000(0000) knlGS:0000000000000000 <4>[ 152.249565] CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033 <4>[ 152.249576] CR2: 00007ffd518816b8 CR3: 000000010591e000 CR4: 00000000000006e0 <4>[ 152.249588] Call Trace: <4>[ 152.249603] <TASK> <4>[ 152.249636] schedule+0x6a/0xf0 <4>[ 152.249658] worker_thread+0xc0/0x3e0 <4>[ 152.249684] ? __pfx_worker_thread+0x10/0x10 <4>[ 152.249704] kthread+0xfc/0x120 <4>[ 152.249721] ? __pfx_kthread+0x10/0x10
I wonder if this is a deadlock related to runqueue lock since another CPU call stack are similarly in schedule.
I tried to run gdb on your vmlinux but it does not have symbols, would it be possible for you to provide a copy of vmlinux with symbols?
Were you able to narrow down the commit/release using git bisect to see when it started happening?
Thank you,
- Joel
HI Joel,
On Thu, 25 May 2023 at 20:51, Joel Fernandes joel@joelfernandes.org wrote:
Hello Naresh,
On Wed, May 24, 2023 at 5:02 AM Naresh Kamboju naresh.kamboju@linaro.org wrote:
Following kernel crash noticed while running perf testing on qemu-x86_64 with stable-rc 6.3.4-rc2 + kselftest merge configs.
Reported-by: Linux Kernel Functional Testing lkft@linaro.org
logs:
INFO: Performing perf record test...
Parse sched tracepoints fields: Ok 16: syscalls:sys_enter_openat event fields : --- start --- test child forked, pid 255 <4>[ 152.221288] int3: 0000 [#1] PREEMPT SMP PTI <4>[ 152.221564] CPU: 0 PID: 255 Comm: perf Not tainted 6.3.4-rc2 #1 <4>[ 152.221607] Hardware name: QEMU Standard PC (Q35 + ICH9, 2009), BIOS 1.14.0-2 04/01/2014 <4>[ 152.221733] RIP: 0010:__schedule+0x29e/0xaa0
<trim>
I wonder if this is a deadlock related to runqueue lock since another CPU call stack are similarly in schedule.
I tried to run gdb on your vmlinux but it does not have symbols, would it be possible for you to provide a copy of vmlinux with symbols?
DEBUG_INFO not enabled on this build.
Were you able to narrow down the commit/release using git bisect to see when it started happening?
I will bisect this problem and get back to you.
Thank you,
- Joel
- Naresh
-
Joel Fernandes -
Naresh Kamboju