XPost: linux.debian.bugs.dist
From: [email protected]

Control: tags -1 + moreinfo

On Thu, Apr 24, 2025 at 08:52:51PM -0700, Alison Chaiken wrote:

The tracer at https://github.com/chaiken/BPF-sandbox/commit/e0dda39cbe92e0f80805a2a06aa80d6fb3b065b2
finally was running when apcupsd triggered the lockup. The stack below has appeared over and over for days. The time output in the trace has a 1000x math error:

2025-04-24T11:20:23.394893-07:00 schallkreis run-investigate-pcie-lockup.sh[2622305]: pci_mmcfg_read() for comm apcupsd with tid 3183 took 222794 s
2025-04-24T11:20:38.809232-07:00 schallkreis run-investigate-pcie-lockup.sh[2622305]: apcupsd: lock contended for 222810s 2025-04-24T11:20:38.809380-07:00 schallkreis run-investigate-pcie-lockup.sh[2622305]: __down_common+521 2025-04-24T11:20:38.809396-07:00 schallkreis run-investigate-pcie-lockup.sh[2622305]: __down_common+521 2025-04-24T11:20:38.809406-07:00 schallkreis run-investigate-pcie-lockup.sh[2622305]: down_timeout+85 2025-04-24T11:20:38.809420-07:00 schallkreis run-investigate-pcie-lockup.sh[2622305]: acpi_os_wait_semaphore+76 2025-04-24T11:20:38.809431-07:00 schallkreis run-investigate-pcie-lockup.sh[2622305]: acpi_ut_acquire_mutex+58 2025-04-24T11:20:38.809444-07:00 schallkreis run-investigate-pcie-lockup.sh[2622305]:
acpi_ex_enter_interpreter+16
2025-04-24T11:20:38.809458-07:00 schallkreis run-investigate-pcie-lockup.sh[2622305]:
acpi_ex_system_wait_mutex+82
2025-04-24T11:20:38.809470-07:00 schallkreis run-investigate-pcie-lockup.sh[2622305]:
acpi_ds_begin_method_execution+137
2025-04-24T11:20:38.809482-07:00 schallkreis run-investigate-pcie-lockup.sh[2622305]:
acpi_ds_call_control_method+79
2025-04-24T11:20:38.809493-07:00 schallkreis run-investigate-pcie-lockup.sh[2622305]: acpi_ps_parse_aml+718 2025-04-24T11:20:38.809504-07:00 schallkreis run-investigate-pcie-lockup.sh[2622305]: acpi_ps_execute_method+319 2025-04-24T11:20:38.809515-07:00 schallkreis run-investigate-pcie-lockup.sh[2622305]: acpi_ns_evaluate+318 2025-04-24T11:20:38.809528-07:00 schallkreis run-investigate-pcie-lockup.sh[2622305]: acpi_evaluate_object+334 2025-04-24T11:20:38.809539-07:00 schallkreis run-investigate-pcie-lockup.sh[2622305]: acpi_device_set_power+495 2025-04-24T11:20:38.809551-07:00 schallkreis run-investigate-pcie-lockup.sh[2622305]:
acpi_pci_set_power_state+109
2025-04-24T11:20:38.809562-07:00 schallkreis run-investigate-pcie-lockup.sh[2622305]: pci_power_up+48 2025-04-24T11:20:38.809573-07:00 schallkreis run-investigate-pcie-lockup.sh[2622305]: pci_pm_runtime_resume+51 2025-04-24T11:20:38.809584-07:00 schallkreis run-investigate-pcie-lockup.sh[2622305]: __rpm_callback+65 2025-04-24T11:20:38.809596-07:00 schallkreis run-investigate-pcie-lockup.sh[2622305]: rpm_callback+85 2025-04-24T11:20:38.809608-07:00 schallkreis run-investigate-pcie-lockup.sh[2622305]: rpm_resume+1235 2025-04-24T11:20:38.809618-07:00 schallkreis run-investigate-pcie-lockup.sh[2622305]: rpm_resume+723 2025-04-24T11:20:38.809630-07:00 schallkreis run-investigate-pcie-lockup.sh[2622305]: __pm_runtime_resume+75 2025-04-24T11:20:38.809641-07:00 schallkreis run-investigate-pcie-lockup.sh[2622305]: usb_autoresume_device+30 2025-04-24T11:20:38.809651-07:00 schallkreis run-investigate-pcie-lockup.sh[2622305]: usbdev_open+259 2025-04-24T11:20:38.809662-07:00 schallkreis run-investigate-pcie-lockup.sh[2622305]: chrdev_open+178 2025-04-24T11:20:38.809673-07:00 schallkreis run-investigate-pcie-lockup.sh[2622305]: do_dentry_open+332 2025-04-24T11:20:38.809685-07:00 schallkreis run-investigate-pcie-lockup.sh[2622305]: vfs_open+46 2025-04-24T11:20:38.809698-07:00 schallkreis run-investigate-pcie-lockup.sh[2622305]: path_openat+2094 2025-04-24T11:20:38.809708-07:00 schallkreis run-investigate-pcie-lockup.sh[2622305]: do_filp_open+196 2025-04-24T11:20:38.809719-07:00 schallkreis run-investigate-pcie-lockup.sh[2622305]: do_sys_openat2+174 2025-04-24T11:20:38.809730-07:00 schallkreis run-investigate-pcie-lockup.sh[2622305]: __x64_sys_openat+85 2025-04-24T11:20:38.809742-07:00 schallkreis run-investigate-pcie-lockup.sh[2622305]: do_syscall_64+130 2025-04-24T11:20:38.809753-07:00 schallkreis run-investigate-pcie-lockup.sh[2622305]:
entry_SYSCALL_64_after_hwframe+118

Here is the failure shortly thereafter. It happened while the system was idle except for browser, IRC etc. left running. Perhaps he pulseaudio failure is related?

2025-04-24T11:22:43.698237-07:00 schallkreis plasmashell[3874]: org.kde.pulseaudio: context kaput
2025-04-24T11:22:43.698345-07:00 schallkreis plasmashell[3874]: org.kde.pulseaudio: No object for name "alsa_output.pci-0000_73_00.6.analog-stereo"
2025-04-24T11:22:43.698364-07:00 schallkreis plasmashell[3874]: org.kde.pulseaudio: No object for name "alsa_output.pci-0000_73_00.6.analog-stereo.monitor" 2025-04-24T11:22:44.139668-07:00 schallkreis kded6[3770]:
org.kde.pulseaudio: context kaput
2025-04-24T11:22:44.139719-07:00 schallkreis kded6[3770]:
org.kde.pulseaudio: No object for name "alsa_output.pci-0000_73_00.6.analog-stereo"
2025-04-24T11:22:44.139733-07:00 schallkreis kded6[3770]:
org.kde.pulseaudio: No object for name "alsa_output.pci-0000_73_00.6.analog-stereo.monitor" 2025-04-24T11:22:44.139817-07:00 schallkreis systemd[3492]: pulseaudio.service: Main process exited, code=killed, status=9/KILL 2025-04-24T11:22:44.580911-07:00 schallkreis systemd[3492]: pulseaudio.service: Failed with result 'signal'.

[continued in next message]

--- SoupGate-Win32 v1.05
* Origin: you cannot sedate... all the things you hate (1:229/2)