Bug 218185

Summary:	ISA soundcard SoundBlaster AWE32 snd-sbawe.ko freezes the system with pipewire/wireplumber
Product:	Linux	Reporter:	Taketo Kabe (kkabe)
Component:	Kernel	Assignee:	Virtual assignee for kernel bugs (linux-kernel)
Status:	NEW ---
Severity:	normal	CC:	tiwai
Priority:	P3
Hardware:	i386
OS:	Linux
Kernel Version:	6.6.2	Subsystem:
Regression:	No	Bisected commit-id:

Description Taketo Kabe 2023-11-24 04:32:21 UTC

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

Comment 1 Taketo Kabe 2023-11-25 17:22:52 UTC

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.

Comment 2 Takashi Iwai 2023-11-27 08:08:46 UTC

Thanks.  It'd be appreciated if you can bisect.

Comment 3 Takashi Iwai 2023-11-27 09:57:20 UTC

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.

Comment 4 Taketo Kabe 2023-11-29 12:29:53 UTC

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

Comment 5 Taketo Kabe 2023-12-03 12:24:52 UTC

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

Comment 6 Taketo Kabe 2023-12-04 10:56:43 UTC

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>

Comment 7 Taketo Kabe 2023-12-13 10:37:58 UTC

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.

Comment 8 Taketo Kabe 2023-12-18 11:41:41 UTC

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.

Comment 9 Taketo Kabe 2023-12-18 11:56:52 UTC

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.

Comment 10 Taketo Kabe 2023-12-31 11:14:28 UTC

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.

Comment 11 Taketo Kabe 2023-12-31 11:29:27 UTC

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.

Comment 12 Taketo Kabe 2024-01-01 05:10:37 UTC

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.

Comment 13 Taketo Kabe 2024-02-04 05:12:07 UTC

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

Comment 14 Taketo Kabe 2024-05-01 10:01:26 UTC

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?

Comment 15 Takashi Iwai 2024-05-02 15:39:14 UTC

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.

Comment 16 Taketo Kabe 2024-05-14 12:44:29 UTC

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 .