[Pkg-utopia-maintainers] Bug#1093142: pipewire-bin: excessive CPU use and errors from pipewire

[Diederik de Haas]

On Sat Jan 18, 2025 at 2:57 PM CET, Russell Coker wrote:
> I've had the same problem again on that phone but not had it happen on my 
> other OP6.  So I think that there may be a hardware issue causing the kernel 
> issue.
>
> But I still believe that there is a bug in pipewire.  In spite of the kernel 
> misbehaving the daemon should still be able to act in a reasonable manner - 
> which may mean just refusing to use the sound hardware in question.

It may not be a hardware problem, but just some kind of issue which
happens sometimes. I haven't figured out what the trigger is/could be.

I have a Pine64 Quartz64 Model A, which is my headless 'build server'
and some days ago I noticed a high CPU usage too. This didn't make any
sense to me is there is nothing audio related connected to the device.

Looking at htop showed me that next to pipewire, there was this:
``/usr/bin/fluidsynth -is /usr/share/sounds/sf3/default-GM.sf3``

When I restarted pipewire, things seemed to have normalized a bit, but
not completely (subjectively).

```sh
diederik at quartz64a:~$ journalctl -b 0 --user -u pipewire.service
mrt 11 12:45:50 quartz64a systemd[993]: Started pipewire.service - PipeWire Multimedia Service.
mrt 11 12:45:51 quartz64a pipewire[1013]: spa.alsa: open failed: Invalid argument

diederik at quartz64a:~$ systemctl --user status pipewire.service
● pipewire.service - PipeWire Multimedia Service
     Loaded: loaded (/usr/lib/systemd/user/pipewire.service; enabled; preset: enabled)
     Active: active (running) since Tue 2025-03-11 12:45:50 CET; 4min 45s ago
 Invocation: 79933b8ba5434c239a437604b11fd0bd
TriggeredBy: ● pipewire.socket
   Main PID: 1013 (pipewire)
      Tasks: 3 (limit: 9098)
     Memory: 7M (peak: 8.7M)
        CPU: 1min 15.149s
     CGroup: /user.slice/user-1000.slice/user at 1000.service/session.slice/pipewire.service
             └─1013 /usr/bin/pipewire

mrt 11 12:45:50 quartz64a systemd[993]: Started pipewire.service - PipeWire Multimedia Service.
mrt 11 12:45:51 quartz64a pipewire[1013]: spa.alsa: open failed: Invalid argument
diederik at quartz64a:~$ wpctl status
PipeWire 'pipewire-0' [1.4.0, diederik at quartz64a, cookie:2787891504]
 └─ Clients:
        33. WirePlumber                         [1.4.0, diederik at quartz64a, pid:1019]
        34. pipewire                            [1.4.0, diederik at quartz64a, pid:1021]
        35. PipeWire ALSA [fluidsynth]          [1.4.0, diederik at quartz64a, pid:1017]
        47. WirePlumber [export]                [1.4.0, diederik at quartz64a, pid:1019]
        73. wpctl                               [1.4.0, diederik at quartz64a, pid:1150]

Audio
 ├─ Devices:
 │      48. Built-in Audio                      [alsa]
 │      49. Built-in Audio                      [alsa]
 │      50. Built-in Audio                      [alsa]
 │
 ├─ Sinks:
 │      44. Built-in Audio Stereo               [vol: 0.40]
 │  *   54. Built-in Audio Stereo               [vol: 0.40]
 │      55. Built-in Audio Stereo               [vol: 0.40]
 │
 ├─ Sources:
 │  *   56. Built-in Audio Stereo               [vol: 1.00]
 │
 ├─ Filters:
 │
 └─ Streams:
        46. PipeWire ALSA [fluidsynth]
             69. output_FL       > fe400000.i2s-i2s-hifi i2s-hifi-0:playback_FL [active]
             70. output_FR       > fe400000.i2s-i2s-hifi i2s-hifi-0:playback_FR [active]

Video
 ├─ Devices:
 │      51. rockchip,rk3568-vpu-dec             [v4l2]
 │      52. rockchip-rga                        [v4l2]
 │      53. rockchip,rk3568-vepu-enc            [v4l2]
 │
 ├─ Sinks:
 │
 ├─ Sources:
 │
 ├─ Filters:
 │
 └─ Streams:

Settings
 └─ Default Configured Devices:
```

It's a mystery to me why there is a fluidsynth stream ...
I'm still not sure whether this is a pipewire or a fluidsynth bug, but
there is https://bugs.debian.org/1075976 which seems similar/related.

Looking a bit further wrt "spa.alsa" reported by systemctl and found:

```sh
diederik at quartz64a:~$ journalctl --user -u pipewire.service
... [mostly fine, but with older pipewire versions ... ]
sep 12 16:29:48 quartz64a systemd[909]: Started pipewire.service - PipeWire Multimedia Service.
sep 12 16:29:49 quartz64a pipewire[926]: spa.alsa: 'hw:1,0': playback open failed: Invalid argument
sep 12 16:29:49 quartz64a pipewire[926]: mod.adapter: 0xaaab1e890e80: can't get format: Invalid argument
sep 12 16:29:49 quartz64a pipewire[926]: mod.adapter: usage: node.name=<string>
sep 12 16:29:49 quartz64a pipewire[926]: spa.alsa: 'hw:1,0': capture open failed: Invalid argument
sep 12 16:29:49 quartz64a pipewire[926]: mod.adapter: 0xaaab1e890e80: can't get format: Invalid argument
sep 12 16:29:49 quartz64a pipewire[926]: mod.adapter: usage: node.name=<string>
sep 12 16:30:27 quartz64a systemd[909]: Stopping pipewire.service - PipeWire Multimedia Service...
sep 12 16:30:27 quartz64a systemd[909]: Stopped pipewire.service - PipeWire Multimedia Service.
...
okt 23 22:41:09 quartz64a systemd[1051]: Started pipewire.service - PipeWire Multimedia Service.
okt 23 22:41:10 quartz64a pipewire[1068]: spa.alsa: 'hw:0,0': playback open failed: Invalid argument
okt 23 22:41:10 quartz64a pipewire[1068]: mod.adapter: 0xaaaaedb8dd00: can't get format: Invalid argument
okt 23 22:41:10 quartz64a pipewire[1068]: mod.adapter: usage: node.name=<string>
nov 01 19:48:31 quartz64a systemd[1051]: Stopping pipewire.service - PipeWire Multimedia Service...
nov 01 19:48:31 quartz64a systemd[1051]: Stopped pipewire.service - PipeWire Multimedia Service.
```

Dunno what to make of that though.

I also found a LOT of "graph xrun not-triggered (N suppressed)":

```sh
root at quartz64a:~# journalctl -b -1 | grep pipewire
Mar 08 10:08:30 quartz64a systemd[1000]: Listening on pipewire-pulse.socket - PipeWire PulseAudio.
Mar 08 10:08:30 quartz64a systemd[1000]: Listening on pipewire.socket - PipeWire Multimedia System Sockets.
Mar 08 10:08:30 quartz64a systemd[1000]: Started pipewire.service - PipeWire Multimedia Service.
Mar 08 10:08:31 quartz64a systemd[1000]: Started pipewire-pulse.service - PipeWire PulseAudio.
Mar 08 10:08:31 quartz64a dbus-daemon[609]: [system] Activating via systemd: service name='org.freedesktop.RealtimeKit1' unit='rtkit-daemon.service' requested by ':1.7' (uid=1000 pid=1020 comm="/usr/bin/pipewire")
Mar 08 10:08:33 quartz64a pipewire[1020]: pw.node: (alsa_output.platform-hdmi-sound.stereo-fallback-57) graph xrun not-triggered (0 suppressed)
Mar 08 10:08:33 quartz64a pipewire[1020]: pw.node: (alsa_output.platform-hdmi-sound.stereo-fallback-57) xrun state:0xffff962dc008 pending:0/2 s:86430890920 a:86431848198 f:86432103415 waiting:957278 process:255217 status:triggered
Mar 08 10:08:38 quartz64a pipewire[1020]: pw.node: (alsa_output.platform-hdmi-sound.stereo-fallback-57) graph xrun not-triggered (0 suppressed)
Mar 08 10:08:38 quartz64a pipewire[1020]: pw.node: (alsa_output.platform-hdmi-sound.stereo-fallback-57) xrun state:0xffff962dc008 pending:0/2 s:91966752344 a:91967108772 f:91967857503 waiting:356428 process:748731 status:triggered
Mar 08 10:09:50 quartz64a pipewire[1020]: pw.node: (alsa_output.platform-hdmi-sound.stereo-fallback-57) graph xrun not-triggered (0 suppressed)
Mar 08 10:09:50 quartz64a pipewire[1020]: pw.node: (alsa_output.platform-hdmi-sound.stereo-fallback-57) xrun state:0xffff962dc008 pending:1/2 s:163784341467 a:163784643060 f:163784702853 waiting:301593 process:59793 status:triggered
Mar 08 10:09:50 quartz64a pipewire[1020]: pw.node: (alsa_playback.fluidsynth-58) xrun state:0xffff962d9008 pending:0/1 s:163785732759 a:163784394844 f:163784529014 waiting:18446744073708213701 process:134170 status:triggered
Mar 08 10:09:54 quartz64a pipewire[1020]: pw.node: (alsa_output.platform-hdmi-sound.stereo-fallback-57) graph xrun not-triggered (368 suppressed)
Mar 08 10:09:54 quartz64a pipewire[1020]: pw.node: (alsa_output.platform-hdmi-sound.stereo-fallback-57) xrun state:0xffff962dc008 pending:0/2 s:167995377007 a:167998332555 f:167998422392 waiting:2955548 process:89837 status:triggered
Mar 08 10:10:32 quartz64a pipewire[1020]: pw.node: (alsa_output.platform-hdmi-sound.stereo-fallback-57) graph xrun not-triggered (14 suppressed)
Mar 08 10:10:32 quartz64a pipewire[1020]: pw.node: (alsa_output.platform-hdmi-sound.stereo-fallback-57) xrun state:0xffff962dc008 pending:0/2 s:205463660932 a:205463771769 f:205463793061 waiting:110837 process:21292 status:triggered
Mar 08 10:10:52 quartz64a pipewire[1020]: pw.node: (alsa_output.platform-hdmi-sound.stereo-fallback-57) graph xrun not-triggered (20 suppressed)
Mar 08 10:10:52 quartz64a pipewire[1020]: pw.node: (alsa_output.platform-hdmi-sound.stereo-fallback-57) xrun state:0xffff962dc008 pending:0/2 s:225416295819 a:225420491281 f:225420522782 waiting:4195462 process:31501 status:triggered
Mar 08 10:14:21 quartz64a pipewire[1020]: spa.alsa: hw:2p: (0 suppressed) snd_pcm_avail after recover: Broken pipe
Mar 08 10:17:43 quartz64a pipewire[1020]: pw.node: (alsa_output.platform-hdmi-sound.stereo-fallback-57) graph xrun not-triggered (5 suppressed)
Mar 08 10:17:43 quartz64a pipewire[1020]: pw.node: (alsa_output.platform-hdmi-sound.stereo-fallback-57) xrun state:0xffff962dc008 pending:1/2 s:636695298581 a:636695722386 f:636695795013 waiting:423805 process:72627 status:triggered
Mar 08 10:17:43 quartz64a pipewire[1020]: pw.node: (alsa_playback.fluidsynth-58) xrun state:0xffff962d9008 pending:0/1 s:636696714375 a:636695420210 f:636695609799 waiting:18446744073708257451 process:189589 status:triggered
Mar 08 12:46:00 quartz64a pipewire[1020]: pw.node: (alsa_output.platform-hdmi-sound.stereo-fallback-57) graph xrun not-triggered (0 suppressed)
Mar 08 12:46:00 quartz64a pipewire[1020]: pw.node: (alsa_output.platform-hdmi-sound.stereo-fallback-57) xrun state:0xffff962dc008 pending:1/2 s:9533530626408 a:9533530805497 f:9533530836998 waiting:179089 process:31501 status:triggered
Mar 08 12:46:00 quartz64a pipewire[1020]: pw.node: (alsa_playback.fluidsynth-58) xrun state:0xffff962d9008 pending:0/1 s:9533532153331 a:9533530674534 f:9533530772538 waiting:18446744073708072819 process:98004 status:triggered

[ literally 100s of similar lines omitted ... ]

Mar 10 21:08:15 quartz64a pipewire[1020]: pw.node: (alsa_output.platform-hdmi-sound.stereo-fallback-57) graph xrun not-triggered (13 suppressed)
Mar 10 21:08:15 quartz64a pipewire[1020]: pw.node: (alsa_output.platform-hdmi-sound.stereo-fallback-57) xrun state:0xffff962dc008 pending:0/2 s:212468537262565 a:212468540158025 f:212468540230360 waiting:2895460 process:72335 status:triggered
Mar 10 21:08:42 quartz64a pipewire[1020]: pw.node: (alsa_output.platform-hdmi-sound.stereo-fallback-57) graph xrun not-triggered (5 suppressed)
Mar 10 21:08:42 quartz64a pipewire[1020]: pw.node: (alsa_output.platform-hdmi-sound.stereo-fallback-57) xrun state:0xffff962dc008 pending:0/2 s:212495552177236 a:212495552459286 f:212495552507121 waiting:282050 process:47835 status:triggered
Mar 10 21:08:44 quartz64a pipewire[1020]: pw.node: (alsa_output.platform-hdmi-sound.stereo-fallback-57) graph xrun not-triggered (78 suppressed)
Mar 10 21:08:44 quartz64a pipewire[1020]: pw.node: (alsa_output.platform-hdmi-sound.stereo-fallback-57) xrun state:0xffff962dc008 pending:1/2 s:212497680193160 a:212497680464710 f:212497680510794 waiting:271550 process:46084 status:triggered
Mar 10 21:08:44 quartz64a pipewire[1020]: pw.node: (alsa_playback.fluidsynth-58) xrun state:0xffff962d9008 pending:0/1 s:212497681574534 a:212497680282996 f:212497680425917 waiting:18446744073708260078 process:142921 status:triggered
Mar 10 21:08:48 quartz64a pipewire[1020]: pw.node: (alsa_output.platform-hdmi-sound.stereo-fallback-57) graph xrun not-triggered (167 suppressed)
Mar 10 21:08:48 quartz64a pipewire[1020]: pw.node: (alsa_output.platform-hdmi-sound.stereo-fallback-57) xrun state:0xffff962dc008 pending:0/2 s:212501707679144 a:212501707909275 f:212501707962360 waiting:230131 process:53085 status:triggered
Mar 10 21:08:52 quartz64a pipewire[1020]: pw.node: (alsa_output.platform-hdmi-sound.stereo-fallback-57) graph xrun not-triggered (73 suppressed)
Mar 10 21:08:52 quartz64a pipewire[1020]: pw.node: (alsa_output.platform-hdmi-sound.stereo-fallback-57) xrun state:0xffff962dc008 pending:1/2 s:212505835821471 a:212505836105563 f:212505836154272 waiting:284092 process:48709 status:triggered
Mar 10 21:08:52 quartz64a pipewire[1020]: pw.node: (alsa_playback.fluidsynth-58) xrun state:0xffff962d9008 pending:0/1 s:212505837197595 a:212505835892931 f:212505836068520 waiting:18446744073708246952 process:175589 status:triggered
Mar 10 21:09:01 quartz64a pipewire[1020]: pw.node: (alsa_output.platform-hdmi-sound.stereo-fallback-57) graph xrun not-triggered (77 suppressed)
Mar 10 21:09:01 quartz64a pipewire[1020]: pw.node: (alsa_output.platform-hdmi-sound.stereo-fallback-57) xrun state:0xffff962dc008 pending:1/2 s:212514361609096 a:212514361891437 f:212514361946564 waiting:282341 process:55127 status:triggered
Mar 10 21:09:07 quartz64a pipewire[1020]: pw.node: (alsa_output.platform-hdmi-sound.stereo-fallback-57) graph xrun not-triggered (95 suppressed)
Mar 10 21:09:07 quartz64a pipewire[1020]: pw.node: (alsa_output.platform-hdmi-sound.stereo-fallback-57) xrun state:0xffff962dc008 pending:0/2 s:212520428274030 a:212520428625791 f:212520428679750 waiting:351761 process:53959 status:triggered
Mar 10 21:09:52 quartz64a pipewire[1020]: pw.node: (alsa_output.platform-hdmi-sound.stereo-fallback-57) graph xrun not-triggered (54 suppressed)
Mar 10 21:09:52 quartz64a pipewire[1020]: pw.node: (alsa_output.platform-hdmi-sound.stereo-fallback-57) xrun state:0xffff962dc008 pending:1/2 s:212565347821223 a:212565348276237 f:212565348336030 waiting:455014 process:59793 status:triggered
Mar 10 21:09:52 quartz64a pipewire[1020]: pw.node: (alsa_playback.fluidsynth-58) xrun state:0xffff962d9008 pending:0/1 s:212565349436229 a:212565348081106 f:212565348227235 waiting:18446744073708196493 process:146129 status:triggered
Mar 10 21:10:26 quartz64a pipewire[1020]: pw.node: (alsa_output.platform-hdmi-sound.stereo-fallback-57) graph xrun not-triggered (126 suppressed)
Mar 10 21:10:26 quartz64a pipewire[1020]: pw.node: (alsa_output.platform-hdmi-sound.stereo-fallback-57) xrun state:0xffff962dc008 pending:0/2 s:212600195466744 a:212600195749377 f:212600195808587 waiting:282633 process:59210 status:triggered
Mar 10 21:10:55 quartz64a pipewire[1020]: pw.node: (alsa_output.platform-hdmi-sound.stereo-fallback-57) graph xrun not-triggered (143 suppressed)
Mar 10 21:10:55 quartz64a pipewire[1020]: pw.node: (alsa_output.platform-hdmi-sound.stereo-fallback-57) xrun state:0xffff962dc008 pending:1/2 s:212628640486448 a:212628640788332 f:212628640838208 waiting:301884 process:49876 status:triggered
Mar 10 21:10:55 quartz64a pipewire[1020]: pw.node: (alsa_playback.fluidsynth-58) xrun state:0xffff962d9008 pending:0/1 s:212628644593528 a:212628640559658 f:212628640715705 waiting:18446744073705517746 process:156047 status:triggered
Mar 10 21:11:21 quartz64a pipewire[1020]: pw.node: (alsa_output.platform-hdmi-sound.stereo-fallback-57) graph xrun not-triggered (161 suppressed)
Mar 10 21:11:21 quartz64a pipewire[1020]: pw.node: (alsa_output.platform-hdmi-sound.stereo-fallback-57) xrun state:0xffff962dc008 pending:1/2 s:212655079817967 a:212655080195103 f:212655080246146 waiting:377136 process:51043 status:triggered
Mar 10 21:11:21 quartz64a pipewire[1020]: pw.node: (alsa_playback.fluidsynth-58) xrun state:0xffff962d9008 pending:0/1 s:212655081216842 a:212655079900219 f:212655080125684 waiting:18446744073708234993 process:225465 status:triggered
Mar 10 21:11:39 quartz64a pipewire[1020]: pw.node: (alsa_output.platform-hdmi-sound.stereo-fallback-57) graph xrun not-triggered (103 suppressed)
Mar 10 21:11:39 quartz64a pipewire[1020]: pw.node: (alsa_output.platform-hdmi-sound.stereo-fallback-57) xrun state:0xffff962dc008 pending:0/2 s:212673252574232 a:212673252846949 f:212673252898575 waiting:272717 process:51626 status:triggered
Mar 10 22:01:11 quartz64a pipewire[1020]: pw.node: (alsa_output.platform-hdmi-sound.stereo-fallback-57) graph xrun not-triggered (0 suppressed)
Mar 10 22:01:11 quartz64a pipewire[1020]: pw.node: (alsa_output.platform-hdmi-sound.stereo-fallback-57) xrun state:0xffff962dc008 pending:0/2 s:215644519303386 a:215644519725732 f:215644519812944 waiting:422346 process:87212 status:triggered
Mar 10 22:15:58 quartz64a wireplumber[1025]: wireplumber: disconnected from pipewire
Mar 10 22:15:58 quartz64a pipewire[1020]: spa.filter-graph: filter.graph must be an object
Mar 10 22:15:58 quartz64a pipewire[1020]: spa.filter-graph: can't load graph: Invalid argument
Mar 10 22:15:58 quartz64a pipewire[1020]: spa.audioconvert: Can't load filter-graph 0: Operation not supported
Mar 10 22:15:58 quartz64a systemd[1000]: Stopping pipewire.service - PipeWire Multimedia Service...
Mar 10 22:15:58 quartz64a systemd[1000]: Stopped pipewire.service - PipeWire Multimedia Service.
Mar 10 22:15:58 quartz64a systemd[1000]: pipewire.service: Consumed 14h 28min 35.281s CPU time, 8.4M memory peak.
Mar 10 22:15:58 quartz64a systemd[1000]: Started pipewire.service - PipeWire Multimedia Service.
Mar 10 22:15:59 quartz64a pipewire[581841]: spa.alsa: open failed: Invalid argument
```

I don't know if this will actually help towards a resolution, but
1. You're not the only one
2. There is something going on which doesn't look good, although I have
   no idea how/what/why/etc

Cheers,
  Diederik
-------------- next part --------------
A non-text attachment was scrubbed...
Name: signature.asc
Type: application/pgp-signature
Size: 228 bytes
Desc: not available
URL: <http://alioth-lists.debian.net/pipermail/pkg-utopia-maintainers/attachments/20250312/7f0a8c64/attachment-0001.sig>