Re: Perf: RIP: 0010:__schedule on qemu-x86_64
From: Joel Fernandes
Date: Thu May 25 2023 - 11:21:34 EST
Hello Naresh,
On Wed, May 24, 2023 at 5:02 AM Naresh Kamboju
<naresh.kamboju@xxxxxxxxxx> 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@xxxxxxxxxx>
>
> 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