Kernel panic

[emptyVoid]

We have stumbled upon a kernel panic while experimenting with Perforator.

Eccentially we tried to collect profile of a service running on a Kubernetes pod from the node's terminal. While using agent as a command line utility instead of deploying it as a daemonset.

[1780474.899181] Kernel panic - not syncing: Hard LOCKUP
[1780474.899183] CPU: 5 PID: 2766655 Comm: agent Kdump: loaded Tainted: G          I    X  -------  ---  5.14.0-427.76.1.el9_4.x86_64 #1
[1780474.899187] Hardware name: IBM IBM Flex System x240 M5 -[9532ZFP]-/-[9532AC1]-, BIOS -[C4E160A-3.81]- 02/01/2024
[1780474.899189] Call Trace:
[1780474.899191]  <NMI>
[1780474.899193]  dump_stack_lvl+0x34/0x48
[1780474.899200]  panic+0x107/0x2f7
[1780474.899204]  nmi_panic.cold+0xc/0xc
[1780474.899207]  watchdog_overflow_callback+0x11f/0x130
[1780474.899210]  __perf_event_overflow+0x105/0x1e0
[1780474.899215]  handle_pmi_common+0x179/0x420
[1780474.899225]  intel_pmu_handle_irq+0x120/0x2b0
[1780474.899230]  perf_event_nmi_handler+0x28/0x50
[1780474.899234]  nmi_handle+0x5e/0x120
[1780474.899238]  default_do_nmi+0x40/0x130
[1780474.899241]  exc_nmi+0xff/0x130
[1780474.899243]  end_repeat_nmi+0x16/0x67
[1780474.899248] RIP: 0010:native_queued_spin_lock_slowpath+0x72/0x2b0
[1780474.899251] Code: 08 0f 92 c2 8b 45 00 0f b6 d2 c1 e2 08 30 e4 09 d0 a9 00 01 ff ff 0f 85 db 01 00 00 85 c0 74 12 0f b6 45 00 84 c0 74 0a f3 90 <0f> b6 45 00 84 c0 75 f6 b8 01 00 00 00 66 89 45 00 5b 5d 41 5c 41
[1780474.899254] RSP: 0018:ffffae90e6fb7298 EFLAGS: 00000002
[1780474.899256] RAX: 0000000000000001 RBX: ffff89153a90b980 RCX: ffff89153a90bea8
[1780474.899258] RDX: 0000000000000000 RSI: 0000000000000000 RDI: ffff893efff72ec0
[1780474.899259] RBP: ffff893efff72ec0 R08: ffff893efff72828 R09: ffff893efff72828
[1780474.899261] R10: 0000000000000000 R11: 0000000000000000 R12: 0000000000000000
[1780474.899263] R13: 0000000000000087 R14: ffff89153a90c764 R15: 0000000000000005
[1780474.899268]  ? native_queued_spin_lock_slowpath+0x72/0x2b0
[1780474.899271]  ? native_queued_spin_lock_slowpath+0x72/0x2b0
[1780474.899274]  </NMI>
[1780474.899275]  <TASK>
[1780474.899277]  _raw_spin_lock+0x25/0x30
[1780474.899279]  raw_spin_rq_lock_nested+0x19/0x80
[1780474.899282]  try_to_wake_up+0x1e5/0x5d0
[1780474.899287]  __queue_work+0x1d2/0x370
[1780474.899292]  queue_work_on+0x24/0x30
[1780474.899296]  soft_cursor+0x1ab/0x240
[1780474.899301]  bit_cursor+0x38f/0x5d0
[1780474.899305]  ? get_color+0x26/0x120
[1780474.899309]  hide_cursor+0x2e/0xc0
[1780474.899312]  vt_console_print+0x424/0x450
[1780474.899317]  __console_emit_next_record+0x215/0x3e0
[1780474.899323]  console_unlock+0x213/0x320
[1780474.899327]  vprintk_emit+0x1c8/0x250
[1780474.899331]  _printk+0x58/0x73
[1780474.899336]  __warn_printk.cold+0xc/0x63
[1780474.899339]  ? __pfx_cmp_ex_search+0x10/0x10
[1780474.899343]  ? bsearch+0x56/0x80
[1780474.899348]  fixup_exception+0x1b9/0x340
[1780474.899351]  exc_general_protection+0x112/0x400
[1780474.899357]  asm_exc_general_protection+0x22/0x30
[1780474.899361] RIP: 0010:copy_user_short_string+0xa/0x50
[1780474.899365] Code: cc cc cc 89 d0 0f 1f 00 c3 cc cc cc cc 01 ca eb df 66 66 2e 0f 1f 84 00 00 00 00 00 0f 1f 40 00 89 d1 83 e2 07 c1 e9 03 74 12 <4c> 8b 06 4c 89 07 48 8d 76 08 48 8d 7f 08 ff c9 75 ee 21 d2 74 10
[1780474.899367] RSP: 0018:ffffae90e6fb78e8 EFLAGS: 00010002
[1780474.899370] RAX: ffff89469cc00000 RBX: 0000000000000008 RCX: 0000000000000001
[1780474.899372] RDX: 0000000000000000 RSI: 746e756f635f705b RDI: ffffce4ff4743368
[1780474.899373] RBP: 746e756f635f705b R08: 0000000000000000 R09: 000000000000000c
[1780474.899375] R10: ffffae90e6fb7910 R11: 000000000000001f R12: ffff897836ea1cc0
[1780474.899377] R13: ffffce4ff4743368 R14: ffffce4ff4743350 R15: ffffae913ac798b8
[1780474.899382]  copy_from_user_nofault+0x5f/0x90
[1780474.899386]  bpf_probe_read_user+0x18/0x50
[1780474.899391]  bpf_prog_727c84569d3e897d_dwarf_unwind_step_fp+0x64/0x126
[1780474.899395]  bpf_prog_b5b7fbc8d0da3a85_dwarf_unwind_step+0x95/0x139
[1780474.899399]  bpf_prog_7c6e602183de93c5_profiler_stage_collect_stack+0x4a2/0x55d
[1780474.899404]  bpf_prog_ee5ed0bdd45f9c04_profiler_do_sample_impl_other+0x170/0x279
[1780474.899408]  bpf_prog_317f41aeb9e9c24c_profiler_do_sample_other+0x2f/0x3e
[1780474.899412]  bpf_prog_f5c902fb96ce512e_perforator_finish_task_switch+0xa7/0xaf
[1780474.899415]  ? finish_task_switch.isra.0+0x1/0x2a0
[1780474.899418]  trace_call_bpf+0xa4/0x150
[1780474.899422]  ? finish_task_switch.isra.0+0x1/0x2a0
[1780474.899424]  ? finish_task_switch.isra.0+0x1/0x2a0
[1780474.899427]  kprobe_perf_func+0x4f/0x270
[1780474.899431]  ? finish_task_switch.isra.0+0x1/0x2a0
[1780474.899434]  ? finish_task_switch.isra.0+0x1/0x2a0
[1780474.899436]  ? kprobe_perf_func+0x4f/0x270
[1780474.899440]  ? finish_task_switch.isra.0+0x1/0x2a0
[1780474.899443]  ? finish_task_switch.isra.0+0x5/0x2a0
[1780474.899445]  kprobe_ftrace_handler+0x11e/0x200
[1780474.899450]  xsk_diag_init+0xcc/0xff0 [xsk_diag]
[1780474.899455]  ? finish_task_switch.isra.0+0x1/0x2a0
[1780474.899458]  finish_task_switch.isra.0+0x5/0x2a0
[1780474.899461]  __schedule+0x223/0x550
[1780474.899465]  schedule+0x2d/0x70
[1780474.899468]  futex_wait_queue+0x70/0xd0
[1780474.899471]  futex_wait+0x175/0x260
[1780474.899474]  ? file_update_time+0x4d/0xd0
[1780474.899480]  do_futex+0x12d/0x1d0
[1780474.899483]  __x64_sys_futex+0x73/0x1d0
[1780474.899486]  do_syscall_64+0x5c/0x90
[1780474.899489]  ? syscall_exit_to_user_mode+0x19/0x40
[1780474.899493]  ? do_syscall_64+0x69/0x90
[1780474.899496]  ? syscall_exit_to_user_mode+0x19/0x40
[1780474.899499]  ? do_syscall_64+0x69/0x90
[1780474.899502]  ? syscall_exit_to_user_mode+0x19/0x40
[1780474.899505]  ? do_syscall_64+0x69/0x90
[1780474.899508]  ? do_syscall_64+0x69/0x90
[1780474.899511]  ? sysvec_apic_timer_interrupt+0x3c/0x90
[1780474.899514]  entry_SYSCALL_64_after_hwframe+0x77/0xe1
[1780474.899518] RIP: 0033:0x1eacee3
[1780474.899527] Code: 24 20 c3 cc cc cc cc 48 8b 7c 24 08 8b 74 24 10 8b 54 24 14 4c 8b 54 24 18 4c 8b 44 24 20 44 8b 4c 24 28 b8 ca 00 00 00 0f 05 <89> 44 24 30 c3 cc cc cc cc cc cc cc cc cc cc cc cc cc cc cc cc cc
[1780474.899529] RSP: 002b:00007f28196809e0 EFLAGS: 00000286 ORIG_RAX: 00000000000000ca
[1780474.899532] RAX: ffffffffffffffda RBX: 0000000000000000 RCX: 0000000001eacee3
[1780474.899534] RDX: 0000000000000000 RSI: 0000000000000080 RDI: 000000c000700140
[1780474.899535] RBP: 00007f2819680a28 R08: 0000000000000000 R09: 0000000000000000
[1780474.899537] R10: 0000000000000000 R11: 0000000000000286 R12: 0000000000001d78
[1780474.899539] R13: 0000000000000001 R14: 000000c0007021c0 R15: 000000000000001d
[1780474.899543]  </TASK>

[cezarnik]

Hi! Sorry for late reply. Could you please check if the problem persists on stable kernel 5.15.193 from https://www.kernel.org/ ?

[emptyVoid]

Hi, @cezarnik!

We've experienced no issues running agent to collect profiles outside of Kuberetes environment on a slightly older kernel: 5.14.0-427.59.1.el9_4.x86_64. It seems unlikely to be a kernel issue.

Not sure if I can replicate the problem on another kernel since majority of our tools and services are built for RHEL 9.4, which doesn't feature kernel 5.15.

[cezarnik]

Could you please try to collect CPUClock event instead of CPUCycles to check if the problem persists? It can be written in agent config like this

perf_events:
    -
        type: CPUCycles
        frequency: 99

[emptyVoid]

We actually used CPUClock since it is specified in agent's configuration:

perforator/perforator/deploy/kubernetes/helm/perforator/config/agent.yaml

Line 21 in 027821e

- type: CPUClock

Changing perf event to TaskClock seems to work. Not sure how good it is though.

We are yet to try CPUCycles. Couldn't enable it in our test environment due to ENOENT error, maybe since it is running on VM.