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 <[email protected]>
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-364-ga37c304c022d/testrun/17169996/suite/log-parser-test/test/check-kernel-panic/log
- https://qa-reports.linaro.org/lkft/linux-stable-rc-linux-6.3.y/build/v6.3.3-364-ga37c304c022d/testrun/17169996/suite/log-parser-test/tests/
- https://storage.tuxsuite.com/public/linaro/lkft/builds/2QCeuajqUTZlyC4kEyQGxT6YwYv/
- https://storage.tuxsuite.com/public/linaro/lkft/builds/2QCeuajqUTZlyC4kEyQGxT6YwYv/config
--
Linaro LKFT
https://lkft.linaro.org
Hello Naresh,
On Wed, May 24, 2023 at 5:02 AM Naresh Kamboju
<[email protected]> 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 <[email protected]>
>
> 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 <[email protected]> wrote:
>
> Hello Naresh,
>
> On Wed, May 24, 2023 at 5:02 AM Naresh Kamboju
> <[email protected]> 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 <[email protected]>
> >
> > 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