Kernel: 6.6.2 pipewire-0.3.80-1 (Fedora 39 version) wireplumber-0.4.14-2 (Fedora 39 version) Soundcard: Creative SoundBlaster AWE32 (snd-sbawe.ko) CPU: Pentium (P54C) 120MHz Mmeory: 1GB Symptom: invoking wireplumber after the soundcard module snd-sbawe.ko load freezes the entire system. Steps to reproduce: Since this soundcard is an ISA PnP card, driver is not loaded automativcally on boot. Manually load: # modprobe snd-sbawe seq_ports=0 Check if ALSA is working: # alay -D plughw:0 /usr/share/sounds/alsa/Front-Center.wav Works. So far, so good. # systemctl --user start pipewire pipewire-pulse wireplumber freezes the entire system (after brief "top" showing 30% CPU usage of wireplumber, which is normal) Serial console does not have any interesting message: [ 405.192389] fbcon: radeondrmfb (fb0) is primary device [ 405.474790] Console: switching to colour frame buffer device 170x48 [ 405.973621] radeon 0000:01:00.0: [drm] fb0: radeondrmfb frame buffer device [ 494.400038] sbawe 01:01.00: activated [ 494.461230] sbawe 01:01.02: activated Mishaps on userland (wireplumber) should not cause system freeze, so I consider this a kernel bug. Results by other soundcards: YMF744B (PCI card, snd-ymfpci.ko): wireplumber works (pw-play -v Front_Center.wav) ES1868F (ISA card, snd-es18xx.ko): wireplumber works (pw-play -v Front_Center.wav) Vibra16 (ISA card, snd-sb16.ko): Only "Front" part of Front_Center.wav is played by aplay -D plughw:0, not working properly on ALSA level, different issue SoundBlaster Live!(PCI card, snd-emu10k1.ko): driver cannot wake the card to D0 state; different issue
Rewond back to kernel-6.0.19, and have same problem (pipewire/wireplumber freezes system when snd-sbawe is loaded). I don't know whether this is a reression or not (since older kernel haven't been used with pipewire) but I'll try.
Thanks. It'd be appreciated if you can bisect.
At first I thought that the problem were in emu8000 PCM code. But, now I noticed that you passed seq_ports=0 to snd-sbawe, so the emu8000 isn't used at all, and the culprit is likely something else.
Rewound back to kernel-5.15.0. THe problem got slight change: When "modprobe snd-sbawe seq_ports=0" "systemctl --user start pipewire wireplumber" is invoked: - Total lockup of entire system does not occur. - System acts slloowwwly. - "top" shows around 40.0 sy of system CPU usage, with no userland process using the CPU. - Second invocation of "pw-play /usr/share/sounds/alsa/Front_Center.wav" makes system state back to expected (no system CPU usage in quiscent state). I guess there is two problems: - total lockup of system - high CPU usage by system when wireplumber is invoked
Rewound back to kernel-5.11.0. System locks up, no system slowdown even observed. $ sudo modprobe snd-sbawe seq_ports=0 $ systemctl --user start pipewire wireplumber locks up the whole system, after a little pop sound and with "top" breifly showing 40% CPU usage of wireplumber. No interesting output on serial console: [ 322.583948] ppdev: user-space parallel port driver [ 325.991660] e100 0000:00:12.0 enp0s18: renamed from eth0 [ 329.253963] e100 0000:00:12.0 enp0s18: NIC Link is Up 100 Mbps Full Duplex [ 329.266408] IPv6: ADDRCONF(NETDEV_CHANGE): enp0s18: link becomes ready [ 342.600789] [drm] VGACON disable radeon kernel modesetting. << due to "nomodeset" kernel option [ 342.604460] [drm:radeon_module_init [radeon]] *ERROR* No UMS support in radeon module! << due to "nomodeset" kernel option [ 644.303498] sbawe 01:01.00: activated [ 644.364843] sbawe 01:01.02: activated
kernel-5.11.0 pipewire-0.3.80-1 (Fedora 39 version) wireplumber-0.4.14-2 (Fedora 39 version) Dump of /var/log/messages, with wireplumber invoked with WIREPLUMBER_DEBUG=D (Debug) environment. Does this chime something? Dec 4 19:29:08 cygnus systemd[474]: Reloading. Dec 4 19:29:49 cygnus kernel: sbawe 01:01.00: activated Dec 4 19:29:49 cygnus kernel: sbawe 01:01.02: activated Dec 4 19:29:57 cygnus systemd[474]: Reached target Sound Card. Dec 4 19:29:57 cygnus systemd[1]: Save/Restore Sound Card State was skipped because of an unmet condition check (ConditionPathExists=!/etc/alsa/state-daemon.conf). Dec 4 19:29:57 cygnus systemd[1]: Started Manage Sound Card State (restore and store). Dec 4 19:29:57 cygnus systemd[1]: Reached target Sound Card. Dec 4 19:29:58 cygnus alsactl[616]: alsactl 1.2.8 daemon started Dec 4 19:29:58 cygnus alsactl[616]: alsa-lib main.c:1559:(snd_use_case_mgr_open) error: failed to import hw:0 use case configuration -2 Dec 4 19:30:17 cygnus systemd[474]: Created slice User Core Session Slice. Dec 4 19:30:17 cygnus systemd[474]: Started PipeWire Multimedia Service. Dec 4 19:30:18 cygnus systemd[474]: Started Multimedia Service Session Manager. Dec 4 19:30:18 cygnus systemd[1]: Starting system activity accounting tool... Dec 4 19:30:19 cygnus systemd[1]: sysstat-collect.service: Deactivated successfully. Dec 4 19:30:19 cygnus systemd[1]: Finished system activity accounting tool. Dec 4 19:30:21 cygnus journal[619]: WirePlumber 0.4.14 initializing Dec 4 19:30:21 cygnus journal[619]: version 0.3.80 Dec 4 19:30:21 cygnus systemd[474]: Starting D-Bus User Message Bus... Dec 4 19:30:21 cygnus journal[619]: 0x145ff80: loaded config '/usr/share/wireplumber/wireplumber.conf' with 4 items Dec 4 19:30:21 cygnus journal[619]: handle config '/usr/share/wireplumber/wireplumber.conf' section 'context.properties' Dec 4 19:30:21 cygnus journal[619]: 0x145fc20: parsed 2 context.properties items Dec 4 19:30:21 cygnus journal[619]: handle config '/usr/share/wireplumber/wireplumber.conf' section 'context.spa-libs' Dec 4 19:30:21 cygnus journal[619]: 0x145fc20: parsed 6 context.spa-libs items Dec 4 19:30:21 cygnus journal[619]: handle config '/usr/share/wireplumber/wireplumber.conf' section 'context.modules' Dec 4 19:30:21 cygnus journal[619]: 0x145fc20: name:libpipewire-module-rt args:{#012 nice.level = -11#012 #rt.prio = 88#012 #rt.time.soft = -1#012 #rt.time.hard = -1#012 } Dec 4 19:30:22 cygnus journal[619]: Clamp rtprio 88 to 0 Dec 4 19:30:22 cygnus journal[619]: Priority max (0) must be at least 11 Dec 4 19:30:22 cygnus dbus-broker-launch[621]: Service file '/usr/share/dbus-1/services/org.kde.dolphin.FileManager1.service' is not named after the D-Bus name 'org.freedesktop.FileManager1'. Dec 4 19:30:22 cygnus dbus-broker-launch[621]: Service file '/usr/share/dbus-1/services/org.kde.kscreen.service' is not named after the D-Bus name 'org.kde.KScreen'. Dec 4 19:30:22 cygnus dbus-broker-launch[621]: Service file '/usr/share/dbus-1/services/imsettings-daemon.service' is not named after the D-Bus name 'com.redhat.imsettings'. Dec 4 19:30:22 cygnus dbus-broker-launch[621]: Service file '/usr/share/dbus-1/services/org.kde.plasma.Notifications.service' is not named after the D-Bus name 'org.freedesktop.Notifications'. Dec 4 19:30:22 cygnus dbus-broker-launch[621]: Policy to allow eavesdropping in /usr/share/dbus-1/session.conf +31: Eavesdropping is deprecated and ignored Dec 4 19:30:22 cygnus dbus-broker-launch[621]: Policy to allow eavesdropping in /usr/share/dbus-1/session.conf +33: Eavesdropping is deprecated and ignored Dec 4 19:30:22 cygnus systemd[474]: Started D-Bus User Message Bus. Dec 4 19:30:23 cygnus journal[621]: Ready Dec 4 19:30:23 cygnus journal[619]: Can't find org.freedesktop.portal.Desktop. Is xdg-desktop-portal running? Dec 4 19:30:23 cygnus journal[619]: found session bus but no portal, trying RTKit fallback Dec 4 19:30:24 cygnus systemd-journald[291]: Data hash table of /run/log/journal/ecbb191ddac04ca494edc34bbd6eb2ab/system.journal has a fill level at 75.0 (3367 of 4487 items, 2584576 file size, 767 bytes per hash table item), suggesting rotation. Dec 4 19:30:24 cygnus systemd-journald[291]: /run/log/journal/ecbb191ddac04ca494edc34bbd6eb2ab/system.journal: Journal header limits reached or header out-of-date, rotating. Dec 4 19:30:24 cygnus rsyslogd[384]: imjournal: journal files changed, reloading... [v8.2102.0-113.el9_2.v1 try https://www.rsyslog.com/e/0 ] Dec 4 19:30:24 cygnus journal[619]: 0x145fc20: loaded module libpipewire-module-rt Dec 4 19:30:25 cygnus journal[619]: 0x145fc20: name:libpipewire-module-protocol-native args:(null) Dec 4 19:30:26 cygnus journal[619]: 0x145fc20: loaded module libpipewire-module-protocol-native Dec 4 19:30:26 cygnus journal[619]: 0x145fc20: name:libpipewire-module-client-node args:(null) Dec 4 19:30:27 cygnus journal[619]: 0x145fc20: loaded module libpipewire-module-client-node Dec 4 19:30:27 cygnus journal[619]: 0x145fc20: name:libpipewire-module-client-device args:(null) Dec 4 19:30:28 cygnus journal[619]: 0x145fc20: loaded module libpipewire-module-client-device Dec 4 19:30:28 cygnus journal[619]: 0x145fc20: name:libpipewire-module-adapter args:(null) Dec 4 19:30:28 cygnus journal[619]: 0x145fc20: loaded module libpipewire-module-adapter Dec 4 19:30:28 cygnus journal[619]: 0x145fc20: name:libpipewire-module-metadata args:(null) Dec 4 19:30:28 cygnus journal[619]: 0x145fc20: loaded module libpipewire-module-metadata Dec 4 19:30:28 cygnus journal[619]: 0x145fc20: name:libpipewire-module-session-manager args:(null) Dec 4 19:30:29 cygnus journal[619]: 0x145fc20: loaded module libpipewire-module-session-manager Dec 4 19:30:29 cygnus journal[619]: 0x145fc20: name:libpipewire-module-spa-node-factory args:(null) Dec 4 19:30:29 cygnus journal[619]: 0x145fc20: loaded module libpipewire-module-spa-node-factory Dec 4 19:30:29 cygnus journal[619]: 0x145fc20: parsed 8 context.modules items Dec 4 19:30:29 cygnus journal[619]: 0x145fc20: parsed 0 context.objects items Dec 4 19:30:29 cygnus journal[619]: 0x145fc20: parsed 0 context.exec items Dec 4 19:30:29 cygnus journal[619]: 0x1478198: add id:0 key:log.level type: value:2 Dec 4 19:30:30 cygnus journal[619]: 0x1478198: add id:0 key:clock.rate type: value:48000 Dec 4 19:30:30 cygnus journal[619]: 0x1478198: add id:0 key:clock.allowed-rates type: value:[ 48000 ] Dec 4 19:30:30 cygnus journal[619]: 0x1478198: add id:0 key:clock.quantum type: value:1024 Dec 4 19:30:30 cygnus journal[619]: 0x1478198: add id:0 key:clock.min-quantum type: value:32 Dec 4 19:30:30 cygnus journal[619]: 0x1478198: add id:0 key:clock.max-quantum type: value:2048 Dec 4 19:30:30 cygnus journal[619]: 0x1478198: add id:0 key:clock.force-quantum type: value:0 Dec 4 19:30:30 cygnus journal[619]: 0x1478198: add id:0 key:clock.force-rate type: value:0 Dec 4 19:30:30 cygnus journal[619]: handle config '/usr/share/wireplumber/wireplumber.conf' section 'wireplumber.components' Dec 4 19:30:30 cygnus systemd[1]: Starting RealtimeKit Scheduling Policy Service... Dec 4 19:30:30 cygnus journal[619]: loading config file: /usr/share/wireplumber/main.lua.d/00-functions.lua Dec 4 19:30:30 cygnus journal[619]: loading config file: /usr/share/wireplumber/main.lua.d/20-default-access.lua Dec 4 19:30:30 cygnus journal[619]: loading config file: /usr/share/wireplumber/main.lua.d/30-alsa-monitor.lua Dec 4 19:30:30 cygnus journal[619]: loading config file: /usr/share/wireplumber/main.lua.d/30-libcamera-monitor.lua Dec 4 19:30:30 cygnus journal[619]: loading config file: /usr/share/wireplumber/main.lua.d/30-v4l2-monitor.lua Dec 4 19:30:30 cygnus journal[619]: loading config file: /usr/share/wireplumber/main.lua.d/40-device-defaults.lua Dec 4 19:30:30 cygnus journal[619]: loading config file: /usr/share/wireplumber/main.lua.d/40-stream-defaults.lua Dec 4 19:30:30 cygnus journal[619]: loading config file: /usr/share/wireplumber/main.lua.d/50-alsa-config.lua Dec 4 19:30:30 cygnus journal[619]: loading config file: /usr/share/wireplumber/main.lua.d/50-default-access-config.lua Dec 4 19:30:30 cygnus journal[619]: loading config file: /usr/share/wireplumber/main.lua.d/50-libcamera-config.lua Dec 4 19:30:30 cygnus journal[619]: loading config file: /usr/share/wireplumber/main.lua.d/50-v4l2-config.lua Dec 4 19:30:30 cygnus journal[619]: loading config file: /usr/share/wireplumber/main.lua.d/90-enable-all.lua Dec 4 19:30:31 cygnus journal[619]: loading config file: /usr/share/wireplumber/policy.lua.d/00-functions.lua Dec 4 19:30:31 cygnus journal[619]: loading config file: /usr/share/wireplumber/policy.lua.d/10-default-policy.lua Dec 4 19:30:31 cygnus journal[619]: loading config file: /usr/share/wireplumber/policy.lua.d/50-endpoints-config.lua Dec 4 19:30:31 cygnus journal[619]: loading config file: /usr/share/wireplumber/policy.lua.d/90-enable-all.lua Dec 4 19:30:31 cygnus systemd[1]: Started RealtimeKit Scheduling Policy Service. Dec 4 19:30:31 cygnus journal[619]: loading config file: /usr/share/wireplumber/bluetooth.lua.d/00-functions.lua Dec 4 19:30:31 cygnus journal[619]: loading config file: /usr/share/wireplumber/bluetooth.lua.d/30-bluez-midi-monitor.lua Dec 4 19:30:31 cygnus journal[619]: loading config file: /usr/share/wireplumber/bluetooth.lua.d/30-bluez-monitor.lua Dec 4 19:30:31 cygnus journal[619]: loading config file: /usr/share/wireplumber/bluetooth.lua.d/50-bluez-config.lua Dec 4 19:30:31 cygnus journal[619]: loading config file: /usr/share/wireplumber/bluetooth.lua.d/50-bluez-midi-config.lua Dec 4 19:30:31 cygnus journal[619]: loading config file: /usr/share/wireplumber/bluetooth.lua.d/90-enable-all.lua Dec 4 19:30:31 cygnus journal[619]: connecting to 'pipewire-0' runtime_dir:/run/user/1001 Dec 4 19:30:32 cygnus journal[619]: connecting to 'pipewire-0' runtime_dir:/run/user/1001 Dec 4 19:30:32 cygnus journal[619]: <WpCore:0x1460018> connected to server: pipewire-0, cookie: 3526726704 Dec 4 19:30:32 cygnus journal[619]: <WpInitTransition:0x1451368> Checking for session manager conflicts... Dec 4 19:30:33 cygnus journal[619]: <WpCore:0x1460098> connected to server: pipewire-0, cookie: 3526726704 Dec 4 19:30:35 cygnus journal[619]: <WpInitTransition:0x1451368> Activating plugins... Dec 4 19:30:35 cygnus journal[619]: <WpFileMonitorApi:0x14912b0> enabling plugin 'file-monitor-api' Dec 4 19:30:35 cygnus journal[619]: <WpDefaultProfile:0x1451ab8> enabling plugin 'default-profile' Dec 4 19:30:35 cygnus journal[619]: <WpDefaultNodes:0x14b40a0> enabling plugin 'default-nodes' Dec 4 19:30:35 cygnus journal[619]: <WpPortalPermissionStorePlugin:0x148e4a0> enabling plugin 'portal-permissionstore' Dec 4 19:30:36 cygnus journal[619]: <WpMetadataPlugin:0x1491280> enabling plugin 'metadata' Dec 4 19:30:36 cygnus journal[619]: <WpReserveDevicePlugin:0x148e5b8> enabling plugin 'reserve-device' Dec 4 19:30:36 cygnus journal[619]: <WpMixerApi:0x1451ba8> enabling plugin 'mixer-api' Dec 4 19:30:36 cygnus journal[619]: <WpDefaultNodesApi:0x148f620> enabling plugin 'default-nodes-api' Dec 4 19:30:36 cygnus journal[619]: <WpLogind:0x148ebc0> enabling plugin 'logind' Dec 4 19:30:37 cygnus rtkit-daemon[629]: Successfully made thread 618 of process 618 (/usr/bin/pipewire) owned by '1001' high priority at nice level -11. Dec 4 19:30:37 cygnus journal[619]: <WpInitTransition:0x1451368> Executing scripts... Dec 4 19:30:37 cygnus journal[619]: <WpLuaScriptingPlugin:0x148e260> enabling plugin 'lua-scripting' Dec 4 19:30:38 cygnus journal[619]: <WpLuaScript:0x148e298> enabling plugin 'script:policy-device-profile.lua' Dec 4 19:30:38 cygnus journal[619]: <WpLuaScript:0x148e2d0> enabling plugin 'script:monitors/libcamera.lua' Dec 4 19:30:38 cygnus journal[619]: SPA handle 'api.libcamera.enum.manager' could not be loaded; is it installed? Dec 4 19:30:38 cygnus journal[619]: PipeWire's libcamera SPA missing or broken. libcamera not supported. Dec 4 19:30:39 cygnus journal[619]: <WpLuaScript:0x148e308> enabling plugin 'script:access/access-default.lua' Dec 4 19:30:39 cygnus journal[619]: <WpLuaScript:0x148e340> enabling plugin 'script:monitors/alsa-midi.lua' Dec 4 19:30:39 cygnus journal[619]: <WpLuaScript:0x148e378> enabling plugin 'script:monitors/alsa.lua' Dec 4 19:30:39 cygnus journal[619]: Activating ALSA monitor Dec 4 19:30:39 cygnus journal[619]: <WpLuaScript:0x148e3b0> enabling plugin 'script:policy-device-routes.lua' Dec 4 19:30:39 cygnus journal[619]: <WpLuaScript:0x148e430> enabling plugin 'script:restore-stream.lua' Dec 4 19:30:39 cygnus journal[619]: <WpLuaScript:0x148e468> enabling plugin 'script:suspend-node.lua' Dec 4 19:30:39 cygnus journal[619]: <WpLuaScript:0x148e510> enabling plugin 'script:access/access-portal.lua' Dec 4 19:30:39 cygnus journal[619]: <WpLuaScript:0x148e548> enabling plugin 'script:monitors/v4l2.lua' Dec 4 19:30:39 cygnus journal[619]: <WpLuaScript:0x148e580> enabling plugin 'script:intended-roles.lua' Dec 4 19:30:39 cygnus journal[619]: <WpLuaScript:0x148ea38> enabling plugin 'script:policy-endpoint-client.lua' Dec 4 19:30:39 cygnus journal[619]: <WpLuaScript:0x148ea70> enabling plugin 'script:static-endpoints.lua' Dec 4 19:30:39 cygnus journal[619]: <WpLuaScript:0x148eaa8> enabling plugin 'script:policy-bluetooth.lua' Dec 4 19:30:39 cygnus journal[619]: <WpLuaScript:0x148eae0> enabling plugin 'script:policy-endpoint-device.lua' Dec 4 19:30:39 cygnus journal[619]: <WpLuaScript:0x148eb18> enabling plugin 'script:policy-endpoint-client-links.lua' Dec 4 19:30:39 cygnus journal[619]: <WpLuaScript:0x148eb50> enabling plugin 'script:policy-node.lua' Dec 4 19:30:40 cygnus journal[619]: <WpLuaScript:0x148eb88> enabling plugin 'script:create-item.lua' Dec 4 19:30:40 cygnus rtkit-daemon[629]: Successfully made thread 626 of process 618 (/usr/bin/pipewire) owned by '1001' RT at priority 20. Dec 4 19:30:40 cygnus journal[619]: <WpLuaScript:0x148ec40> enabling plugin 'script:monitors/bluez.lua' Dec 4 19:30:40 cygnus journal[619]: <WpLogind:0x148ebc0> Seat state changed: active Dec 4 19:30:40 cygnus journal[619]: Bluetooth codec plugin api.codec.bluez5.media.aptx not available Dec 4 19:30:40 cygnus journal[619]: Bluetooth codec plugin api.codec.bluez5.media.lc3plus not available Dec 4 19:30:41 cygnus journal[619]: Bluetooth codec plugin api.codec.bluez5.media.lc3 not available Dec 4 19:30:41 cygnus journal[619]: main thread nice level set to -11 Dec 4 19:30:41 cygnus journal[619]: clamping requested priority 88 for thread 627 between 1 and 20 Dec 4 19:30:41 cygnus journal[619]: acquired realtime priority 20 for thread 627 using RTKit Dec 4 19:30:41 cygnus journal[619]: Registering DBus media object manager: /MediaEndpoint Dec 4 19:30:41 cygnus journal[619]: Registering DBus media object manager: /MediaEndpointLE Dec 4 19:30:41 cygnus journal[619]: Registering DBus media endpoint: /MediaEndpoint/A2DPSource/ldac Dec 4 19:30:41 cygnus journal[619]: Registering DBus media endpoint: /MediaEndpoint/A2DPSource/aac Dec 4 19:30:41 cygnus journal[619]: Registering DBus media endpoint: /MediaEndpoint/A2DPSink/aac Dec 4 19:30:41 cygnus journal[619]: Registering DBus media endpoint: /MediaEndpoint/A2DPSource/sbc Dec 4 19:30:41 cygnus journal[619]: Registering DBus media endpoint: /MediaEndpoint/A2DPSink/sbc Dec 4 19:30:41 cygnus journal[619]: Registering DBus media endpoint: /MediaEndpoint/A2DPSource/sbc_xq Dec 4 19:30:41 cygnus journal[619]: Registering DBus media endpoint: /MediaEndpoint/A2DPSink/sbc_xq Dec 4 19:30:41 cygnus journal[619]: Registering DBus media endpoint: /MediaEndpoint/A2DPSource/faststream Dec 4 19:30:41 cygnus journal[619]: Registering DBus media endpoint: /MediaEndpoint/A2DPSource/faststream_duplex Dec 4 19:30:41 cygnus journal[619]: Registering DBus media endpoint: /MediaEndpoint/A2DPSource/opus_05 Dec 4 19:30:42 cygnus journal[619]: Registering DBus media endpoint: /MediaEndpoint/A2DPSink/opus_05 Dec 4 19:30:42 cygnus journal[619]: Registering DBus media endpoint: /MediaEndpoint/A2DPSource/opus_05_duplex Dec 4 19:30:42 cygnus journal[619]: Registering DBus media endpoint: /MediaEndpoint/A2DPSink/opus_05_duplex Dec 4 19:30:42 cygnus rtkit-daemon[629]: Successfully made thread 619 of process 619 (/usr/bin/wireplumber) owned by '1001' high priority at nice level -11. Dec 4 19:30:43 cygnus journal[619]: Failed to get percentage from UPower: org.freedesktop.DBus.Error.NameHasNoOwner Dec 4 19:30:44 cygnus journal[619]: start inotify Dec 4 19:30:45 cygnus journal[619]: Enabling the use of ACP on alsa_card._sys_devices_pnp1_01_01_sound_card0 Dec 4 19:30:45 cygnus journal[619]: start inotify Dec 4 19:30:45 cygnus rtkit-daemon[629]: Successfully made thread 627 of process 619 (/usr/bin/wireplumber) owned by '1001' RT at priority 20. Dec 4 19:30:47 cygnus journal[619]: error: failed to import hw:0 use case configuration -2 Dec 4 19:30:47 cygnus journal[619]: error: failed to import Sound Blaster 16 use case configuration -2 Dec 4 19:30:47 cygnus journal[619]: UCM not available for card Sound Blaster 16 Dec 4 19:30:49 cygnus journal[619]: Unknown parameters 0 Dec 4 19:30:49 cygnus journal[619]: Unknown PCM front:0 Dec 4 19:30:49 cygnus journal[619]: Error opening PCM device front:0: Invalid argument <NUL chars follow, dure to partial write to /var/log/messages>
Rewound back to kernel-5.4.0 Still same problem; $ sudo modprobe snd-sbawe seq_ports=0 $ aplay -D plughw:0 /usr/share/sounds/alsa/Front_Center.wav #works $ systemctl --user start pipewire wireplumber freezes the entire system, after a little pop audio sound. I had to also rewind alsa-lib and alsa-utils to 1.2.1, circa 2019.
Since kernel-5.4 is an LTS, I tried kernel-5.4.263 (it's becoming harder and harder to compile old kernel with modern buildtools) Problem persists. $ sudo modprobe snd-sbawe seq_ports=0 $ aplay -D plughw:0 /usr/share/sounds/alsa/Front_Center.wav # Works $ systemctl --user start pipewire wireplumber system freezes.
I have found out that if you do NOT check ALSA by aplay, and on newer kernel, system freeze does not occur: On kernel-5.4.263 and kernel-6.6.3: $ sudo modprobe snd-sbawe seq_ports=0 $ systemctl --user start pipewire wireplumber "top" shows"50.0 sy", system acts slowly, but does not freeze. Then issuing $ pw-play /usr/share/sounds/alsa/Front_Center.wav and waiting for couple of minutes, will play the sound, and CPU usage goes down to sane state. kernel-5.4.0 freezes the system by above sequence. Look like on newer kernel, system freeze is avoided by making pipewire the first process to grab the sound device. That will be normal for non-ISAPnP, PCI sound devices, so problem may not appear on such hardware. CPU "50.0 sy" seems to sill be some bug though.
Rewound back to kernel-5.0.0. It still freezes the entire system by the following sequence: $ sudo modprobe snd-sbawe seq_ports=0 $ systemctl --user start pipewire wireplumber Whole tree of kernel-5.x, 6.x seems to be tainted.
Meanwhile, on newer kernels, following action will does not lock up the system (newer: kernel-5.4.263, kernel-5.11.0 and newer) $ systemctl --user mask wireplumber $ sudo modprobe snd-sbawe seq_ports=0 $ systemctl --user start pipewire -- only pipewire starts $ wireplumber & -- system does not lock up, but acts slowly, -- showing around "50.0 sy" in "top" $ pw-play /usr/share/sounds/alsa/Front_Center.wav -- after couple of minutes, sound is played, and CPU usage goes down to normal I'm starting to feel that this is not a regression but a new bug tickled by pipewire, since sb-awe.ko had been never tested against pipewire. (maybe experienced pulseadudio) How should I debug this kind of bug? "perf record -a -g wireplumber" does not show any interesting results, since the CPU binding thread seems not in userland's call chain.
This is journalctl excerpt of kernel-6.6.2. "pipewire[615]: spa.alsa: hw:0: snd_pcm_status error: Inappropriate ioctl for device" of last part of journal is output after CPU usage is down, so not particulary interesting. $ systemctl --user mask wireplumber $ sudo modprobe snd-sbawe seq_ports=0 $ logger -p daemon.info starting pipewire $ systemctl --user start pipewire $ systemctl --user unmask wireplumber $ logger -p daemon.info starting wireplumber $ systemctl --user start wireplumber # cpu usage goes up to 50% $ logger -p daemon.info starting wire/pw-play $ pw-play /usr/share/sounds/alsa/Front_Center.wav # after couple of minutes, sound plays, and cpu usage goes down to normal Jan 01 13:23:07 cygnus.five.ten sudo[570]: kabe : TTY=tty1 ; PWD=/home/kabe ; USER=root ; COMMAND=/sbin/modprobe snd-sbawe seq_ports=0 Jan 01 13:23:07 cygnus.five.ten sudo[570]: pam_unix(sudo:session): session opened for user root(uid=0) by kabe(uid=1001) Jan 01 13:23:14 cygnus.five.ten kernel: sbawe 01:01.00: [dma 1] Jan 01 13:23:14 cygnus.five.ten kernel: sbawe 01:01.00: [dma 5] Jan 01 13:23:14 cygnus.five.ten kernel: sbawe 01:01.00: [io 0x0220-0x022f] Jan 01 13:23:14 cygnus.five.ten kernel: sbawe 01:01.00: [io 0x0330-0x0331] Jan 01 13:23:14 cygnus.five.ten kernel: sbawe 01:01.00: [io 0x0388-0x038b] Jan 01 13:23:14 cygnus.five.ten kernel: sbawe 01:01.00: activated Jan 01 13:23:14 cygnus.five.ten kernel: sbawe 01:01.02: [io 0x0620-0x0623] Jan 01 13:23:15 cygnus.five.ten kernel: sbawe 01:01.02: [io 0x0a20-0x0a23] Jan 01 13:23:15 cygnus.five.ten kernel: sbawe 01:01.02: [io 0x0e20-0x0e23] Jan 01 13:23:15 cygnus.five.ten kernel: sbawe 01:01.02: activated Jan 01 13:23:15 cygnus.five.ten sudo[570]: pam_unix(sudo:session): session closed for user root Jan 01 13:23:37 cygnus.five.ten kabe[613]: starting pipewire Jan 01 13:23:48 cygnus.five.ten systemd[500]: Created slice User Core Session Slice. Jan 01 13:23:49 cygnus.five.ten systemd[500]: Started PipeWire Multimedia Service. Jan 01 13:23:50 cygnus.five.ten systemd[500]: Starting D-Bus User Message Bus... Jan 01 13:23:51 cygnus.five.ten dbus-broker-launch[616]: Service file '/usr/share/dbus-1/services/org.kde.dolphin.FileManager1.service' is not named after the D-Bus name 'org.freedesktop.FileManager1'. Jan 01 13:23:51 cygnus.five.ten dbus-broker-launch[616]: Service file '/usr/share/dbus-1/services/org.kde.kscreen.service' is not named after the D-Bus name 'org.kde.KScreen'. Jan 01 13:23:51 cygnus.five.ten dbus-broker-launch[616]: Service file '/usr/share/dbus-1/services/imsettings-daemon.service' is not named after the D-Bus name 'com.redhat.imsettings'. Jan 01 13:23:51 cygnus.five.ten dbus-broker-launch[616]: Service file '/usr/share/dbus-1/services/org.kde.plasma.Notifications.service' is not named after the D-Bus name 'org.freedesktop.Notifications'. Jan 01 13:23:51 cygnus.five.ten dbus-broker-launch[616]: Policy to allow eavesdropping in /usr/share/dbus-1/session.conf +31: Eavesdropping is deprecated and ignored Jan 01 13:23:51 cygnus.five.ten dbus-broker-launch[616]: Policy to allow eavesdropping in /usr/share/dbus-1/session.conf +33: Eavesdropping is deprecated and ignored Jan 01 13:23:51 cygnus.five.ten systemd[500]: Started D-Bus User Message Bus. Jan 01 13:23:52 cygnus.five.ten dbus-broker-lau[616]: Ready Jan 01 13:23:53 cygnus.five.ten systemd[1]: Starting RealtimeKit Scheduling Policy Service... Jan 01 13:23:53 cygnus.five.ten systemd[1]: Started RealtimeKit Scheduling Policy Service. Jan 01 13:23:53 cygnus.five.ten rtkit-daemon[619]: Successfully called chroot. Jan 01 13:23:54 cygnus.five.ten rtkit-daemon[619]: Successfully dropped privileges. Jan 01 13:23:54 cygnus.five.ten rtkit-daemon[619]: Successfully limited resources. Jan 01 13:23:54 cygnus.five.ten rtkit-daemon[619]: Canary thread running. Jan 01 13:23:54 cygnus.five.ten rtkit-daemon[619]: Watchdog thread running. Jan 01 13:23:54 cygnus.five.ten rtkit-daemon[619]: Running. Jan 01 13:23:54 cygnus.five.ten rtkit-daemon[619]: Supervising 0 threads of 0 processes of 0 users. Jan 01 13:23:54 cygnus.five.ten rtkit-daemon[619]: Supervising 0 threads of 0 processes of 0 users. Jan 01 13:23:54 cygnus.five.ten rtkit-daemon[619]: Supervising 0 threads of 0 processes of 0 users. Jan 01 13:23:57 cygnus.five.ten rtkit-daemon[619]: Successfully made thread 615 of process 615 (/usr/bin/pipewire) owned by '1001' high priority at nice level -11. Jan 01 13:23:57 cygnus.five.ten rtkit-daemon[619]: Supervising 1 threads of 1 processes of 1 users. Jan 01 13:23:58 cygnus.five.ten rtkit-daemon[619]: Successfully made thread 620 of process 615 (/usr/bin/pipewire) owned by '1001' RT at priority 20. Jan 01 13:23:58 cygnus.five.ten rtkit-daemon[619]: Supervising 2 threads of 1 processes of 1 users. Jan 01 13:24:09 cygnus.five.ten systemd[500]: Reloading. Jan 01 13:24:30 cygnus.five.ten kabe[632]: starting wireplumber Jan 01 13:24:37 cygnus.five.ten systemd[500]: Started Multimedia Service Session Manager. Jan 01 13:24:39 cygnus.five.ten rtkit-daemon[619]: Supervising 2 threads of 1 processes of 1 users. Jan 01 13:24:39 cygnus.five.ten rtkit-daemon[619]: Supervising 2 threads of 1 processes of 1 users. Jan 01 13:24:39 cygnus.five.ten rtkit-daemon[619]: Supervising 2 threads of 1 processes of 1 users. Jan 01 13:24:41 cygnus.five.ten rtkit-daemon[619]: Successfully made thread 634 of process 634 (/usr/bin/wireplumber) owned by '1001' high priority at nice level -11. Jan 01 13:24:41 cygnus.five.ten rtkit-daemon[619]: Supervising 3 threads of 2 processes of 1 users. Jan 01 13:24:42 cygnus.five.ten wireplumber[634]: Failed to set scheduler settings: Operation not permitted Jan 01 13:24:43 cygnus.five.ten rtkit-daemon[619]: Successfully made thread 636 of process 634 (/usr/bin/wireplumber) owned by '1001' RT at priority 20. Jan 01 13:24:43 cygnus.five.ten rtkit-daemon[619]: Supervising 4 threads of 2 processes of 1 users. Jan 01 13:24:44 cygnus.five.ten wireplumber[634]: SPA handle 'api.libcamera.enum.manager' could not be loaded; is it installed? Jan 01 13:24:44 cygnus.five.ten wireplumber[634]: PipeWire's libcamera SPA missing or broken. libcamera not supported. Jan 01 13:24:46 cygnus.five.ten wireplumber[634]: Failed to get percentage from UPower: org.freedesktop.DBus.Error.NameHasNoOwner Jan 01 13:24:47 cygnus.five.ten wireplumber[634]: GetManagedObjects() failed: org.freedesktop.DBus.Error.NameHasNoOwner Jan 01 13:25:46 cygnus.five.ten kabe[649]: starting wire/pw-play Jan 01 13:26:11 cygnus.five.ten rtkit-daemon[619]: Supervising 4 threads of 2 processes of 1 users. Jan 01 13:26:13 cygnus.five.ten rtkit-daemon[619]: Supervising 4 threads of 2 processes of 1 users. Jan 01 13:26:14 cygnus.five.ten rtkit-daemon[619]: Supervising 4 threads of 2 processes of 1 users. Jan 01 13:26:33 cygnus.five.ten systemd[500]: Created slice User Background Tasks Slice. Jan 01 13:26:34 cygnus.five.ten polkitd[397]: Error evaluating authorization rules Jan 01 13:26:40 cygnus.five.ten systemd[500]: Starting Mark boot as successful... Jan 01 13:26:48 cygnus.five.ten systemd[500]: Starting Cleanup of User's Temporary Files and Directories... Jan 01 13:26:53 cygnus.five.ten systemd[500]: Finished Mark boot as successful. Jan 01 13:27:36 cygnus.five.ten systemd[500]: Finished Cleanup of User's Temporary Files and Directories. Jan 01 13:27:37 cygnus.five.ten systemd[500]: systemd-tmpfiles-clean.service: Consumed 7.092s CPU time. Jan 01 13:27:39 cygnus.five.ten pipewire[615]: spa.alsa: hw:0: snd_pcm_status error: Inappropriate ioctl for device Jan 01 13:30:29 cygnus.five.ten systemd[1]: Starting system activity accounting tool... Jan 01 13:30:29 cygnus.five.ten systemd[1]: sysstat-collect.service: Deactivated successfully. Jan 01 13:30:29 cygnus.five.ten systemd[1]: Finished system activity accounting tool.
I'm still trying to find where the "50.0 sy" of top comes from, but "perf record" seems to not catching the hot part of the kernel code. Is there a way to debug this? Procedure tried: sysstemctl --user mask pipewire wireplumber sudo sh -c 'echo -1 > /proc/sys/kernel/perf_event_paranoid; echo 0 > /proc/sys/kernel/kptr_restrict' ulimit -n unlimited #open files ulimit -u unlimited #processes sudo modprobe snd-sbawe pipewire & sleep 10 wireplumber & sleep 30 perf record -a --call-graph dwarf --proc-map-timeout=10000 --mmap-flush=4k --freq=99 pw-play /usr/share/sounds/alsa/Front_Center.wav perf report Result of "perf report": Samples: 1K of event 'cpu-clock:pppH', Event count (approx.): 13656565520 Children Self Command Shared Object Symbol + 28.99% 0.07% perf perf [.] __cmd_record.constprop.0 + 28.55% 0.07% perf perf [.] record__mmap_read_evlist + 28.55% 0.00% perf [kernel.kallsyms] [k] do_int80_syscall_32 + 28.48% 0.07% perf perf [.] perf_data_file__write + 28.25% 0.07% perf perf [.] ion + 28.25% 0.00% perf libc.so.6 [.] __GI___write (inlined) + 28.11% 0.00% perf [kernel.kallsyms] [k] __ia32_sys_write + 28.11% 0.00% perf [kernel.kallsyms] [k] ksys_write + 28.03% 0.07% perf [kernel.kallsyms] [k] vfs_write + 27.66% 0.00% perf [kernel.kallsyms] [k] ext4_file_write_iter + 27.59% 0.00% perf [kernel.kallsyms] [k] ext4_buffered_write_iter + 26.78% 0.00% perf perf [.] perf_mmap__push + 26.78% 0.07% perf perf [.] record__pushfn + 26.26% 0.15% perf [kernel.kallsyms] [k] generic_perform_write + 11.39% 0.30% perf [kernel.kallsyms] [k] ext4_da_write_begin + 10.72% 0.00% pw-play [kernel.kallsyms] [k] restore_all_switch_stack + 10.58% 0.07% pw-play [kernel.kallsyms] [k] do_int80_syscall_32 + 8.95% 0.00% pw-data-loop libc.so.6 [.] __clone3 (inlined) + 8.95% 0.00% pw-data-loop libc.so.6 [.] start_thread + 8.80% 0.30% perf [kernel.kallsyms] [k] copy_page_from_iter_atomic.part.0 + 8.80% 0.07% perf [kernel.kallsyms] [k] copy_page_from_iter_atomic + 8.43% 0.00% pw-data-loop libpipewire-0.3.so.0.1100.0 [.] 0xb7e7d5b8 + 8.28% 8.28% perf [kernel.kallsyms] [k] __copy_user_ll + 8.06% 0.00% pw-data-loop libspa-support.so [.] 0xb79cdc95 + 7.69% 0.00% pw-data-loop libpipewire-0.3.so.0.1100.0 [.] 0xb7e9b9d6 + 7.54% 0.00% pw-data-loop libspa-audioconvert.so [.] 0xb5f14b74 + 7.03% 0.00% pw-data-loop libspa-audioconvert.so [.] 0xb5f23cdc + 6.88% 0.00% pw-data-loop libspa-audioconvert.so [.] 0xb5f2f1e1 + 6.66% 0.52% perf [kernel.kallsyms] [k] __block_write_begin_int + 6.66% 0.00% perf [kernel.kallsyms] [k] __block_write_begin + 6.51% 0.00% wireplumber wireplumber [.] 0x004b24c3 + 6.51% 0.00% wireplumber libglib-2.0.so.0.6800.4 [.] g_main_loop_run + 6.43% 0.00% wireplumber libglib-2.0.so.0.6800.4 [.] 0xb7dc4120
I'm still struggling with this bug (pipewire & wireplumber & keeps CPU 50.0 sy) `perf record` seems to slip through the hotspot of the kernel code, and only shows uninteresting entries like do_int80_syscall_32(). I also tried kgdboc, but all threads (kernel LWP) shows to be in schedule() state. Killing pipewire and wireplumber still keeps 50.0 sy in top, so this is definitely a kind of a kernel bug. How should I track this?
If it were a crash in kernel, you can try kdump. Or you can trigger crash via magic sysrq and analyze a dump, too. You should try to disable MIDI (mpu401) as well. It might be some irq handling there.
It is not crashing, the CPU is kept to 50.0% sy busy with no appearent userland process busy by doing pipewire & wireplumber & Previously I wrote that kgdboc stacktrace shows all kernel threads in schedule(). I tried to get a kdump by kernel option: crashkernel=200M systemctl start kdump echo 1 > /proc/sys/kernel/sysrq echo c > /proc/sysrq-trigger Backtrace is output on console, but crashkernel is not invoked; just sits there. Reproduced on i586, i686 and Hyper-V. This is a different bug, so I'll issue a separate bugreport after trying the latest kernel/kexec-tools .