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 .
Created attachment 308022 [details] patch to honor mpu_port=0 for snd_sbawe, snd_sb16 I am struggling with the bug for a year and only slight progress. > You should try to disable MIDI (mpu401) as well. It might be some irq > handling there. snd_sbawe.ko didn't honor "modprobe snd_sbawe mpu_port=0" and overwrites with values retrieved from ISAPNP, so I had to patch the driver a little to make it work. No progress; "modprobe snd_sbawe mpu_port=0 fm_port=-1 seq_ports=0" "systemctl --user start pipewire wireplumber" makes system cpu usage in "top" from 30.0% to 50.0% sy.
I will post several long output of "perf report". "perf record --freq=33 --call-graph=dwarf --proc-map-timeout=9000 -a sleep 30" (yes, this is a slow machine) "perf report" First, the state of the normal, quiscent, not-slow state: - 98.99% 98.59% swapper [kernel.kallsyms] [k] cpuidle_enter_state is expected. Annotatable place is couple of opcodes after "sti" (enable interrupt) opcode. ============= Samples: 993 of event 'cpu-clock:ppp', Event count (approx.): 30090908790 Children Self Command Shared Object Symbol + 99.50% 0.00% swapper [kernel.kallsyms] [k] startup_32_smp + 99.50% 0.00% swapper [kernel.kallsyms] [k] i386_start_kernel + 99.50% 0.00% swapper [kernel.kallsyms] [k] start_kernel + 99.50% 0.00% swapper [kernel.kallsyms] [k] rest_init + 99.50% 0.00% swapper [kernel.kallsyms] [k] cpu_startup_entry + 99.50% 0.00% swapper [kernel.kallsyms] [k] do_idle + 99.09% 0.10% swapper [kernel.kallsyms] [k] cpuidle_idle_call - 98.99% 98.59% swapper [kernel.kallsyms] [k] cpuidle_enter_state 98.59% startup_32_smp i386_start_kernel start_kernel rest_init cpu_startup_entry do_idle cpuidle_idle_call call_cpuidle cpuidle_enter cpuidle_enter_state + 98.99% 0.00% swapper [kernel.kallsyms] [k] call_cpuidle + 98.99% 0.00% swapper [kernel.kallsyms] [k] cpuidle_enter 0.40% 0.40% swapper [kernel.kallsyms] [k] acpi_safe_halt 0.40% 0.40% swapper [kernel.kallsyms] [k] finish_task_switch 0.40% 0.00% swapper [kernel.kallsyms] [k] schedule_idle 0.40% 0.00% swapper [kernel.kallsyms] [k] __schedule
Now, "perf report" of the slow state: acpi_safe_halt() takes 47% of the time. This time also, the annotatable entry point is couple of opcodes after "sti". This suggests that "perf record" probes are not hitting the hotspot directly but slipping ("skid") to the next "sti". ================ Samples: 1K of event 'cpu-clock:ppp', Event count (approx.): 31606060290 Children Self Command Shared Object Symbol + 83.32% 0.10% swapper [kernel.kallsyms] [k] cpuidle_enter - 83.22% 35.28% swapper [kernel.kallsyms] [k] cpuidle_enter_state - 47.94% cpuidle_enter_state - 47.84% acpi_idle_enter - acpi_safe_halt - asm_common_interrupt common_interrupt irq_exit_rcu __irq_exit_rcu do_softirq_own_stack __softirqentry_text_start handle_softirqs - 35.28% startup_32_smp i386_start_kernel start_kernel rest_init cpu_startup_entry do_idle cpuidle_idle_call call_cpuidle cpuidle_enter cpuidle_enter_state + 47.84% 0.00% swapper [kernel.kallsyms] [k] acpi_idle_enter - 47.84% 47.08% swapper [kernel.kallsyms] [k] acpi_safe_halt - 47.08% startup_32_smp i386_start_kernel start_kernel rest_init cpu_startup_entry do_idle cpuidle_idle_call call_cpuidle cpuidle_enter cpuidle_enter_state acpi_idle_enter acpi_safe_halt + 0.77% acpi_safe_halt + 5.18% 0.00% perf [kernel.kallsyms] [k] restore_all_switch_stack + 5.18% 0.00% perf [kernel.kallsyms] [k] do_int80_syscall_32 + 5.08% 0.00% perf [kernel.kallsyms] [k] ia32_sys_call + 4.99% 0.00% perf perf [.] perf_data_file__write + 4.89% 0.00% perf perf [.] 0x004c08b2 + 4.89% 0.00% perf perf [.] 0x006bde2d + 4.89% 0.00% perf libc.so.6 [.] __GI___libc_write + 4.89% 0.00% perf [kernel.kallsyms] [k] __ia32_sys_write + 4.89% 0.00% perf [kernel.kallsyms] [k] ksys_write
acpi_safe_halt() suggests somethis wring in Power Mangement code, so I tried "apm=off acpi=off" kernel option. The problem is still there. "perf report": =============== Samples: 1K of event 'cpu-clock:ppp', Event count (approx.): 31848484530 Children Self Command Shared Object Symbol + 86.68% 0.19% swapper [kernel.kallsyms] [k] cpuidle_idle_call + 86.68% 0.19% swapper [kernel.kallsyms] [k] default_idle_call - 86.49% 84.78% swapper [kernel.kallsyms] [k] default_idle - 84.78% startup_32_smp i386_start_kernel start_kernel rest_init cpu_startup_entry do_idle cpuidle_idle_call default_idle_call default_idle - 1.71% default_idle asm_common_interrupt common_interrupt irq_exit_rcu __irq_exit_rcu do_softirq_own_stack __softirqentry_text_start handle_softirqs run_timer_softirq - __run_timers - 1.52% call_timer_fn - 0.76% e100_watchdog mii_ethtool_gset mdio_read mdio_ctrl_hw _raw_spin_unlock_irqrestore + 4.95% 0.00% perf [kernel.kallsyms] [k] restore_all_switch_stack + 4.95% 0.00% perf [kernel.kallsyms] [k] do_int80_syscall_32
I suspected wild hardware interrupts from SoundBlaster, but "cat /proc/interrupts" show only negligble amount of interrupts from SoundBlaster. ============= [root@cygnus kabe]# head -23 /proc/interrupts CPU0 0: 124112 XT-PIC timer 1: 726 XT-PIC i8042 2: 0 XT-PIC cascade 5: 13 XT-PIC SoundBlaster 6: 3 XT-PIC floppy 7: 0 XT-PIC parport0 8: 0 XT-PIC rtc0 9: 0 XT-PIC acpi, ehci_hcd:usb1 10: 2594 XT-PIC ohci_hcd:usb3, enp0s18 11: 0 XT-PIC ohci_hcd:usb2 12: 158 XT-PIC i8042 14: 8203 XT-PIC pata_ali 15: 1573 XT-PIC pata_ali NMI: 0 Non-maskable interrupts LOC: 0 Local timer interrupts SPU: 0 Spurious interrupts PMI: 0 Performance monitoring interrupts IWI: 0 IRQ work interrupts RTR: 0 APIC ICR read retries RES: 0 Rescheduling interrupts CAL: 0 Function call interrupts TLB: 0 TLB shootdowns
Anyway, the facts suggest something is wrong inside interrrupt handler running during Interrupt Disabled state, but how do I debug this? Is device driver developers using something different?
Well, it's an ancient card like Antikythera mechanism, so no one else ever tested with a real SB card and pipewire, I guess :) Suppose it's a PCM device that causes a freeze, could you try to adjust snd_sb16_playback and snd_sb16_capture? e.g. increase the period_bytes_min and periods_min. pipewire tries to use a small period size.
Created attachment 308032 [details] adjust snd_sb16_playback and snd_sb16_capture, increase the period_bytes_min and periods_min > adjust snd_sb16_playback and snd_sb16_capture? e.g. increase the > period_bytes_min and periods_min Thanks for the comment. I tried the patch above, but the slowness does not changed much. Constantly around 30% sy of system cpu usage in "top". The slowness is "fixed" (CPU usage plummets down) when I do "aplay -D hw:0 /usr/share/sounds/alsa/Front_Center.wav" . I tracked down by "gdb /usr/bin/aplay", and revealed that "ioctl(fd. SNDRV_PCM_IOCTL_PREPARE) " in alsa-lib will make CPU usage sane. The ioctl handler in sound/core/pcm_native.c is like this: ================= static int snd_pcm_do_prepare(struct snd_pcm_substream *substream, snd_pcm_state_t state) { int err; snd_pcm_sync_stop(substream, true); err = substream->ops->prepare(substream); if (err < 0) return err; return snd_pcm_do_reset(substream, state); } ... static const struct action_ops snd_pcm_action_prepare = { .pre_action = snd_pcm_pre_prepare, .do_action = snd_pcm_do_prepare, .post_action = snd_pcm_post_prepare }; ================= snd_pcm_do_reset() here looks fishy. I feel that snd_pcm_do_reset() is not properly done on device initialization. I am not acquiainted enough on PCM code, so I cannot determine where to add the snd_pcm_do_reset() in other place. Any thoughts?
snd_pcm_do_reset() doesn't do much unless the driver sets up its ioctl PCM ops to do some special action, and the sb driver doesn't do that. So, it's likely rather the driver's prepare PCM ops call. The sb16 has: static int snd_sb16_playback_prepare(struct snd_pcm_substream *substream) { .... snd_sb16_setup_rate(chip, runtime->rate, SNDRV_PCM_STREAM_PLAYBACK); .... snd_dma_program(dma, runtime->dma_addr, size, DMA_MODE_WRITE | DMA_AUTOINIT); .... count = snd_pcm_lib_period_bytes(substream); spin_lock_irqsave(&chip->reg_lock, flags); if (chip->mode & SB_MODE_PLAYBACK_16) { count >>= 1; count--; snd_sbdsp_command(chip, SB_DSP4_OUT16_AI); snd_sbdsp_command(chip, format); snd_sbdsp_command(chip, count & 0xff); snd_sbdsp_command(chip, count >> 8); snd_sbdsp_command(chip, SB_DSP_DMA16_OFF); } else { count--; snd_sbdsp_command(chip, SB_DSP4_OUT8_AI); snd_sbdsp_command(chip, format); snd_sbdsp_command(chip, count & 0xff); snd_sbdsp_command(chip, count >> 8); snd_sbdsp_command(chip, SB_DSP_DMA8_OFF); } spin_unlock_irqrestore(&chip->reg_lock, flags); And you can try to check which part takes time by simple tracing. Each snd_sbdsp_command takes a busy loop, and some of them might take unexpectedly long if the chip doesn't respond well.
Created attachment 308075 [details] sb16 driver with printf and msleep(8100) I sprinkled printk and msleep(8100) (when applicable) all over. The result was, setting DMA parameters to SB16 slows down / back to sane state the kernel. Also I checked the return of snd_sbdsp_command(), which return of failure was silently ignored, but it was not failing. Do I have to send SB_DSP_DMA16_OFF before and after setting DMA parameters? (current code only OFFs after setting DMA parameters) May 03 11:19:28 cygnus.five.ten kernel: snd_pcm_do_prepare:1949: doing substream->ops->prepare(substream) May 03 11:19:28 cygnus.five.ten kernel: snd_sb16_capture_prepare:382: doing snd_sb16_csp_capture_prepare() May 03 11:19:37 cygnus.five.ten kernel: snd_sb16_capture_prepare:385: doing snd_pcm_format_unsigned() May 03 11:19:45 cygnus.five.ten kernel: snd_sb16_capture_prepare:392: doing snd_sb16_setup_rate(chip, runtime->rate=44100, SNDRV_PCM_STREAM_CAPTURE) May 03 11:19:53 cygnus.five.ten kernel: snd_sb16_capture_prepare:397: doing snd_dma_program() May 03 11:19:54 cygnus.five.ten systemd[630]: Starting Mark boot as successful... May 03 11:19:55 cygnus.five.ten systemd[630]: Finished Mark boot as successful. May 03 11:20:02 cygnus.five.ten kernel: snd_sb16_capture_prepare:401: doing snd_pcm_lib_period_bytes(substream) May 03 11:20:10 cygnus.five.ten kernel: snd_sb16_capture_prepare:404: doing DMA off() May 03 11:20:10 cygnus.five.ten kernel: snd_sb16_capture_prepare:411: setting capture DMA 16bit: format=0x30, count=511 May 03 11:20:10 cygnus.five.ten kernel: snd_sb16_capture_prepare:412: sending SB_DSP4_IN16_AI (0xbe) May 03 11:20:10 cygnus.five.ten kernel: snd_sb16_capture_prepare:417: sending format=0x30 May 03 11:20:10 cygnus.five.ten kernel: snd_sb16_capture_prepare:422: sending 0xff of 0x1ff May 03 11:20:10 cygnus.five.ten kernel: snd_sb16_capture_prepare:427: sending 0x1 of 0x1ff May 03 11:20:27 cygnus.five.ten kernel: snd_sb16_capture_prepare:432: sending SB_DSP_DMA16_OFF (0xd5) May 03 11:20:27 cygnus.five.ten kernel: snd_pcm_do_prepare:1954: doing snd_pcm_do_reset(substream, state) May 03 11:20:35 cygnus.five.ten kernel: snd_pcm_do_prepare:1957: returning 0 May 03 11:20:44 cygnus.five.ten kernel: snd_pcm_do_prepare:1949: doing substream->ops->prepare(substream) May 03 11:20:44 cygnus.five.ten kernel: snd_sb16_playback_prepare:256: doing snd_sb16_csp_playback_prepare() May 03 11:20:52 cygnus.five.ten kernel: snd_sb16_playback_prepare:259: setting format May 03 11:20:52 cygnus.five.ten rsyslogd[516]: imjournal: journal files changed, reloading... [v8.2310.0-4.el9.v1 try https://www.rsyslog.com/e/0 ] May 03 11:21:01 cygnus.five.ten kernel: snd_sb16_playback_prepare:266: setting format=0x30 May 03 11:21:01 cygnus.five.ten kernel: snd_sb16_playback_prepare:268: setting snd_sb16_setup_rate(chip, runtime->rate=44100, SNDRV_PCM_STREAM_PLAYBACK May 03 11:21:09 cygnus.five.ten kernel: snd_sb16_playback_prepare:273: setting snd_dma_program(dma,runtime->dma_addr,size=65536, flags=0x58) May 03 11:21:17 cygnus.five.ten kernel: snd_sb16_playback_prepare:277: setting snd_pcm_lib_period_bytes() May 03 11:21:26 cygnus.five.ten kernel: snd_sb16_playback_prepare:280: setting DMA off May 03 11:21:26 cygnus.five.ten kernel: snd_sb16_playback_prepare:287: setting playback DMA 16bit: format=0x30, count=511 May 03 11:21:26 cygnus.five.ten kernel: snd_sb16_playback_prepare:288: sending SB_DSP4_OUT16_AI (0xb6) May 03 11:21:26 cygnus.five.ten kernel: snd_sb16_playback_prepare:293: sending format (0x30) May 03 11:21:26 cygnus.five.ten kernel: snd_sb16_playback_prepare:298: sending 0xff of 0x1ff May 03 11:21:26 cygnus.five.ten kernel: snd_sb16_playback_prepare:303: sending 0x1 of 0x1ff May 03 11:21:34 cygnus.five.ten kernel: snd_sb16_playback_prepare:308: SB_DSP_DMA16_OFF (0xd5) May 03 11:21:34 cygnus.five.ten kernel: snd_sb16_playback_prepare:341: returning 0 May 03 11:21:51 cygnus.five.ten kernel: snd_pcm_do_prepare:1954: doing snd_pcm_do_reset(substream, state) May 03 11:21:54 cygnus.five.ten systemd[584]: Created slice User Background Tasks Slice. May 03 11:21:55 cygnus.five.ten systemd[584]: Starting Cleanup of User's Temporary Files and Directories... May 03 11:21:55 cygnus.five.ten systemd[584]: Finished Cleanup of User's Temporary Files and Directories. May 03 11:21:59 cygnus.five.ten kernel: snd_pcm_do_prepare:1957: returning 0 May 03 11:22:07 cygnus.five.ten kernel: snd_pcm_do_prepare:1949: doing substream->ops->prepare(substream) May 03 11:22:07 cygnus.five.ten kernel: snd_sb16_capture_prepare:382: doing snd_sb16_csp_capture_prepare() May 03 11:22:16 cygnus.five.ten kernel: snd_sb16_capture_prepare:385: doing snd_pcm_format_unsigned() May 03 11:22:24 cygnus.five.ten kernel: snd_sb16_capture_prepare:392: doing snd_sb16_setup_rate(chip, runtime->rate=44100, SNDRV_PCM_STREAM_CAPTURE) May 03 11:22:32 cygnus.five.ten kernel: snd_sb16_capture_prepare:397: doing snd_dma_program() May 03 11:22:41 cygnus.five.ten kernel: snd_sb16_capture_prepare:401: doing snd_pcm_lib_period_bytes(substream) May 03 11:22:49 cygnus.five.ten kernel: snd_sb16_capture_prepare:404: doing DMA off() May 03 11:22:49 cygnus.five.ten kernel: snd_sb16_capture_prepare:447: setting DMA off 8bit: format=0x20, count=1023 May 03 11:22:54 cygnus.five.ten systemd[630]: Created slice User Background Tasks Slice. May 03 11:22:54 cygnus.five.ten systemd[630]: Starting Cleanup of User's Temporary Files and Directories... May 03 11:22:55 cygnus.five.ten systemd[630]: Finished Cleanup of User's Temporary Files and Directories. May 03 11:23:05 cygnus.five.ten kernel: snd_pcm_do_prepare:1954: doing snd_pcm_do_reset(substream, state) May 03 11:23:14 cygnus.five.ten kernel: snd_pcm_do_prepare:1957: returning 0 May 03 11:23:22 cygnus.five.ten kernel: snd_pcm_do_prepare:1949: doing substream->ops->prepare(substream) May 03 11:23:22 cygnus.five.ten kernel: snd_sb16_playback_prepare:256: doing snd_sb16_csp_playback_prepare() May 03 11:23:30 cygnus.five.ten kernel: snd_sb16_playback_prepare:259: setting format May 03 11:23:39 cygnus.five.ten kernel: snd_sb16_playback_prepare:266: setting format=0x30 May 03 11:23:39 cygnus.five.ten kernel: snd_sb16_playback_prepare:268: setting snd_sb16_setup_rate(chip, runtime->rate=44100, SNDRV_PCM_STREAM_PLAYBACK May 03 11:23:47 cygnus.five.ten kernel: snd_sb16_playback_prepare:273: setting snd_dma_program(dma,runtime->dma_addr,size=65536, flags=0x58) May 03 11:23:55 cygnus.five.ten kernel: snd_sb16_playback_prepare:277: setting snd_pcm_lib_period_bytes() May 03 11:24:04 cygnus.five.ten kernel: snd_sb16_playback_prepare:280: setting DMA off May 03 11:24:04 cygnus.five.ten kernel: snd_sb16_playback_prepare:287: setting playback DMA 16bit: format=0x30, count=511 May 03 11:24:04 cygnus.five.ten kernel: snd_sb16_playback_prepare:288: sending SB_DSP4_OUT16_AI (0xb6) May 03 11:24:04 cygnus.five.ten kernel: snd_sb16_playback_prepare:293: sending format (0x30) May 03 11:24:04 cygnus.five.ten kernel: snd_sb16_playback_prepare:298: sending 0xff of 0x1ff May 03 11:24:04 cygnus.five.ten kernel: snd_sb16_playback_prepare:303: sending 0x1 of 0x1ff May 03 11:24:12 cygnus.five.ten kernel: snd_sb16_playback_prepare:308: SB_DSP_DMA16_OFF (0xd5) May 03 11:24:12 cygnus.five.ten kernel: snd_sb16_playback_prepare:341: returning 0 May 03 11:24:29 cygnus.five.ten kernel: snd_pcm_do_prepare:1954: doing snd_pcm_do_reset(substream, state) May 03 11:24:37 cygnus.five.ten kernel: snd_pcm_do_prepare:1957: returning 0 May 03 11:24:45 cygnus.five.ten kernel: snd_pcm_do_prepare:1949: doing substream->ops->prepare(substream) May 03 11:24:45 cygnus.five.ten kernel: snd_sb16_capture_prepare:382: doing snd_sb16_csp_capture_prepare() May 03 11:24:54 cygnus.five.ten kernel: snd_sb16_capture_prepare:385: doing snd_pcm_format_unsigned() May 03 11:25:02 cygnus.five.ten kernel: snd_sb16_capture_prepare:392: doing snd_sb16_setup_rate(chip, runtime->rate=44100, SNDRV_PCM_STREAM_CAPTURE) May 03 11:25:10 cygnus.five.ten kernel: snd_sb16_capture_prepare:397: doing snd_dma_program() May 03 11:25:19 cygnus.five.ten kernel: snd_sb16_capture_prepare:401: doing snd_pcm_lib_period_bytes(substream) May 03 11:25:27 cygnus.five.ten kernel: snd_sb16_capture_prepare:404: doing DMA off() May 03 11:25:27 cygnus.five.ten kernel: snd_sb16_capture_prepare:411: setting capture DMA 16bit: format=0x30, count=511 May 03 11:25:27 cygnus.five.ten kernel: snd_sb16_capture_prepare:412: sending SB_DSP4_IN16_AI (0xbe) May 03 11:25:27 cygnus.five.ten kernel: snd_sb16_capture_prepare:417: sending format=0x30 May 03 11:25:27 cygnus.five.ten kernel: snd_sb16_capture_prepare:422: sending 0xff of 0x1ff May 03 11:25:27 cygnus.five.ten kernel: snd_sb16_capture_prepare:427: sending 0x1 of 0x1ff # kernel slows down here May 03 11:25:44 cygnus.five.ten kernel: snd_sb16_capture_prepare:432: sending SB_DSP_DMA16_OFF (0xd5) May 03 11:25:44 cygnus.five.ten kernel: snd_pcm_do_prepare:1954: doing snd_pcm_do_reset(substream, state) May 03 11:25:52 cygnus.five.ten kernel: snd_pcm_do_prepare:1957: returning 0 ... May 03 11:27:52 cygnus.five.ten kernel: snd_pcm_do_prepare:1949: doing substream->ops->prepare(substream) May 03 11:27:52 cygnus.five.ten kernel: snd_sb16_playback_prepare:256: doing snd_sb16_csp_playback_prepare() May 03 11:28:01 cygnus.five.ten kernel: snd_sb16_playback_prepare:259: setting format May 03 11:28:09 cygnus.five.ten kernel: snd_sb16_playback_prepare:266: setting format=0x0 May 03 11:28:09 cygnus.five.ten kernel: snd_sb16_playback_prepare:268: setting snd_sb16_setup_rate(chip, runtime->rate=44100, SNDRV_PCM_STREAM_PLAYBACK May 03 11:28:17 cygnus.five.ten kernel: snd_sb16_playback_prepare:273: setting snd_dma_program(dma,runtime->dma_addr,size=65536, flags=0x58) May 03 11:28:25 cygnus.five.ten kernel: snd_sb16_playback_prepare:277: setting snd_pcm_lib_period_bytes() May 03 11:28:34 cygnus.five.ten kernel: snd_sb16_playback_prepare:280: setting DMA off May 03 11:28:34 cygnus.five.ten kernel: snd_sb16_playback_prepare:287: setting playback DMA 16bit: format=0x0, count=511 May 03 11:28:34 cygnus.five.ten kernel: snd_sb16_playback_prepare:288: sending SB_DSP4_OUT16_AI (0xb6) May 03 11:28:34 cygnus.five.ten kernel: snd_sb16_playback_prepare:293: sending format (0x0) May 03 11:28:34 cygnus.five.ten kernel: snd_sb16_playback_prepare:298: sending 0xff of 0x1ff May 03 11:28:34 cygnus.five.ten kernel: snd_sb16_playback_prepare:303: sending 0x1 of 0x1ff ## kernel back to sane state here May 03 11:28:42 cygnus.five.ten kernel: snd_sb16_playback_prepare:308: SB_DSP_DMA16_OFF (0xd5) May 03 11:28:42 cygnus.five.ten kernel: snd_sb16_playback_prepare:341: returning 0 May 03 11:28:59 cygnus.five.ten kernel: snd_pcm_do_prepare:1954: doing snd_pcm_do_reset(substream, state)
I heared somewhere that Real Hardware SB16 needs to be programmed to use playback and capture on different DMA channels, such as DMA#5(16bit)for playback and DMA#1(8bit) for capture. The above dump shows that (1) set 16bit transfer for capture (2) set 16bit transfer for playback (3) set 8bit transfer for playback (4) set 16bit transfer for playback (5) set 16bit transfer for capture (kernel slows down here) Is it that some kernel code is needed to prevent usage of DMA16 for both playback and capture?
Created attachment 308110 [details] patch to add force_dma16 module option to snd_sb16/snd_sbawe to allocate 16bit DMA to playback and 8bit DMA to capture, or opposite I think I fixed the problem. - You cannot assign 16-bit DMA to both playback and capture. Doing this will cause unexpected results, like kernel freeze or CPU 50% usage. Probably the chipset DMA was going wild. No wonder that perf nor kgdboc could not catch the problem. - The attached patch adds "force_dma16" module option to snd_sb16/snd_sbawe modules, to assign 16bit DMA to playback and 8bit DMA to capture (or vice versa). Applying this patch, and loading the module by "modprobe snd_sbawe force_dma=1" cleanly fixed the problem. No high CPU usage with pipewire/wirepumber. Playback and Capture both works. - The patch is ugly, especially where nval in snd_sb16_dma_control_put() is overridden. I need someone Who Knows Better to refine the patch. - Keeping force_dma option default to 0 (auto) is not friendly. Should I set the default to 1 (16bit playback, 8bit capture), so casual users are not griefed?
The flag to use exclusively assign 16bit DMA to playback and 8bit DMA to capture or vice versa was already in sb16 code, but the flag to trigger it (chip->force_mode16) was never initialized. Original code was seeding the value from ucontrol->value.enumerated.item[0] . It suggests it is configurable from somewhere, but I was unable to pin down where.
The configuration can be changed via ALSA control API, for example, simply use amixer like: % amixer -c $CARD cset iface=CARD,name='16-bit DMA Allocation' $VAL where $CARD is the card number and $VAL is the value to change from 0 to 2. Usually the mixer setup is saved and restored at each boot, so that the configuration is kept consistent. You can save it manually via % alsactl store $CARD as root, too.
Created attachment 308132 [details] patch to always set DMA on iface=CARD,name='16-bit DMA Allocation' (does not work) Thank you for the info! My patch wasn't needed. But there's still a problem; $ sudo modprobe snd_sbawe $ amixer -c 0 cset iface=CARD,name='16-bit DMA Allocation' 2 #set 16bit DMA to capture $ aplay -D plughw:0 /usr/share/sounds/alsa/Front_Center.wav $ amixer -c 0 cset iface=CARD,name='16-bit DMA Allocation' 1 #set 16bit DMA to playback $ aplay -D plughw:0 /usr/share/sounds/alsa/Front_Center.wav seems to make 16bit DMA allocated both on playback and capture. Oscillating noise is emitted on playback, and CPU usage stays at 20% system, or kernel lockup. Attaqched patch did not work, as chip->playback_substream and chip->capture_substream is set to NULL when device is closed. Is thre any clean way to compensate this? Documenting "iface=CARD,name='16-bit DMA Allocation'" is a set-once value, is easy, but userland misuse should not drive kernel into mischief.
A simple workaround would be to disallow the change during playback or capture, something like below: --- a/sound/isa/sb/sb16_main.c +++ b/sound/isa/sb/sb16_main.c @@ -703,6 +703,9 @@ static int snd_sb16_dma_control_put(struct snd_kcontrol *kcontrol, struct snd_ct unsigned char nval, oval; int change; + if (chip->mode & (SB_MODE_PLAYBACK | SB_MODE_CAPTURE)) + return -EBUSY; + nval = ucontrol->value.enumerated.item[0]; if (nval > 2) return -EINVAL;
Thanks for the response. Unfortunately the patch in https://bugzilla.kernel.org/show_bug.cgi?id=218185#c32 didn't work. When invoking amixer, the device is already closed, so snd_sb16_dma_control_put() never returns -EBUSY . ==== $ amixer -c 0 cset iface=CARD,name='16-bit DMA Allocation' 2 #set 16bit DMA to capture $ aplay -D plughw:0 /usr/share/sounds/alsa/Front_Center.wav $ amixer -c 0 cset iface=CARD,name='16-bit DMA Allocation' 1 #set 16bit DMA to playback $ aplay -D plughw:0 /usr/share/sounds/alsa/Front_Center.wav ==== Oscillating noise is emitted on playback, and CPU usage stays at 40% system, or kernel lockup. I will continue experimenting, but I guess that '16-bit DMA Allocation' is a write-once setting...
Maybe you'd need to disable DMA once when the value gets changed? That is, additionally applying the change like: --- a/sound/isa/sb/sb16_main.c +++ b/sound/isa/sb/sb16_main.c @@ -711,6 +714,10 @@ static int snd_sb16_dma_control_put(struct snd_kcontrol *kcontrol, struct snd_ct change = nval != oval; snd_sb16_set_dma_mode(chip, nval); spin_unlock_irqrestore(&chip->reg_lock, flags); + if (changed) { + snd_dma_disable(chip->dma8); + snd_dma_disable(chip->dma16); + } return change; }
Created attachment 308164 [details] Reset DMA on "amixer -c 0 cset iface=CARD,name='16-bit DMA Allocation' #" The patch https://bugzilla.kernel.org/show_bug.cgi?id=218185#c34 fixed the issue! The following sequence had no problem: ====== modprobe snd_sbawe amixer -c 0 cset iface=CARD,name='16-bit DMA Allocation' 1 aplay -D plughw:0 /usr/share/sounds/alsa/Front_Center.wav amixer -c 0 cset iface=CARD,name='16-bit DMA Allocation' 2 aplay -D plughw:0 /usr/share/sounds/alsa/Front_Center.wav amixer -c 0 cset iface=CARD,name='16-bit DMA Allocation' 1 systemctl --user start pipewire wireplumber aplay -D pipewire /usr/share/sounds/alsa/Front_Center.wav amixer -c 0 cset iface=CARD,name='16-bit DMA Allocation' 2 aplay -D pipewire /usr/share/sounds/alsa/Front_Center.wav amixer -c 0 cset iface=CARD,name='16-bit DMA Allocation' 1 aplay -D pipewire /usr/share/sounds/alsa/Front_Center.wav ====== In your patch, the variable name should be "change", not "changed", so the attached patch is the fixed one.