Pulseaudio continuously creates and frees input streams (and also underruns)
Hello,
we currently have an issue with pulseaudio on two devices that have their audiochip integrated in their soc. This issue doesn't occur on these devices (Raxda Rockpi 3a and Raspberry Pi 3) if either the output is down directly over alsa or if an usb soundcard is used. But we want to stay with pulseaudio because of its mixing functionality that alsa can not provide (not all apps have the dmix plugin).
First the playback start normal. But after a random time the playback starts to sound choppy. The verbose log shows a repeating entry that looks like this (2 entries to recognize the loop, but there have been over 10 million of these looping entries created):
Click to expand
13:32:48 DEV pulseaudio[275035]: Created input 1004305 "ALSA Playback" on alsa_output.platform-rk809-sound.stereo-fallback with sample spec float32le 2ch 44100Hz and channel map front-left,front-right
13:32:48 DEV pulseaudio[275035]: media.name = "ALSA Playback"
13:32:48 DEV pulseaudio[275035]: application.name = "ALSA plug-in [audioplayer]"
13:32:48 DEV pulseaudio[275035]: native-protocol.peer = "UNIX socket client"
13:32:48 DEV pulseaudio[275035]: native-protocol.version = "34"
13:32:48 DEV pulseaudio[275035]: application.process.id = "271089"
13:32:48 DEV pulseaudio[275035]: application.process.user = "echionaudioplayer"
13:32:48 DEV pulseaudio[275035]: application.process.host = "DEV"
13:32:48 DEV pulseaudio[275035]: application.process.binary = "audioplayer"
13:32:48 DEV pulseaudio[275035]: application.language = "C"
13:32:48 DEV pulseaudio[275035]: application.process.machine_id = "f00fd94949434ada8268f65b46c87927"
13:32:48 DEV pulseaudio[275035]: module-stream-restore.id = "sink-input-by-application-name:ALSA plug-in [audioplayer]"
13:32:48 DEV pulseaudio[275035]: Requested tlength=150.00 ms, minreq=10.00 ms
13:32:48 DEV pulseaudio[275035]: Early requests mode enabled, configuring sink latency to minreq.
13:32:48 DEV pulseaudio[275035]: Could not configure a sufficiently low latency. Early requests might not be satisfied.
13:32:48 DEV pulseaudio[275035]: Requested latency=10.00 ms, Received latency=99.95 ms
13:32:48 DEV pulseaudio[275035]: memblockq requested: maxlength=4194304, tlength=52920, base=8, prebuf=3528, minreq=3528 maxrewind=0
13:32:48 DEV pulseaudio[275035]: memblockq sanitized: maxlength=4194304, tlength=52920, base=8, prebuf=3528, minreq=3528 maxrewind=0
13:32:48 DEV pulseaudio[275035]: Final latency 249.95 ms = 130.00 ms + 2*10.00 ms + 99.95 ms
13:32:48 DEV pulseaudio[275035]: Requested volume: front-left: 26214 / 40% / -23.88 dB, front-right: 26214 / 40% / -23.88 dB
13:32:48 DEV pulseaudio[275035]: Got hardware volume: front-left: 26241 / 40% / -23.85 dB, front-right: 26241 / 40% / -23.85 dB
13:32:48 DEV pulseaudio[275035]: Calculated software volume: front-left: 65469 / 100% / -0.03 dB, front-right: 65469 / 100% / -0.03 dB (accurate-enough=yes)
13:32:48 DEV pulseaudio[275035]: Volume not changing
13:32:48 DEV pulseaudio[275035]: alsa_output.platform-rk809-sound.stereo-fallback: state: IDLE -> RUNNING
13:32:48 DEV pulseaudio[275035]: Requesting rewind due to end of underrun.
13:32:48 DEV pulseaudio[275035]: Requested to rewind 17632 bytes.
13:32:48 DEV pulseaudio[275035]: Limited to 17344 bytes.
13:32:48 DEV pulseaudio[275035]: before: 4336
13:32:48 DEV pulseaudio[275035]: after: 4336
13:32:48 DEV pulseaudio[275035]: Rewound 17344 bytes.
13:32:48 DEV pulseaudio[275035]: Processing rewind...
13:32:48 DEV pulseaudio[275035]: latency = 1104
13:32:48 DEV pulseaudio[275035]: Have to rewind 17344 bytes on render memblockq.
13:32:48 DEV pulseaudio[275035]: Processing rewind...
13:32:48 DEV pulseaudio[275035]: Implicit underrun of 'ALSA Playback'
13:32:48 DEV pulseaudio[275035]: alsa_output.platform-rk809-sound.stereo-fallback: Found underrun 15676 bytes ago (1892 bytes ahead in playback buffer)
13:32:48 DEV pulseaudio[275035]: alsa_output.platform-rk809-sound.stereo-fallback: Found underrun 15740 bytes ago (1860 bytes ahead in playback buffer)
13:32:48 DEV pulseaudio[275035]: alsa_output.platform-rk809-sound.stereo-fallback: Found underrun 15932 bytes ago (1700 bytes ahead in playback buffer)
13:32:48 DEV pulseaudio[275035]: alsa_output.platform-rk809-sound.stereo-fallback: Found underrun 15964 bytes ago (1668 bytes ahead in playback buffer)
13:32:48 DEV pulseaudio[275035]: alsa_output.platform-rk809-sound.stereo-fallback: Found underrun 16060 bytes ago (1540 bytes ahead in playback buffer)
13:32:48 DEV pulseaudio[275035]: alsa_output.platform-rk809-sound.stereo-fallback: Found underrun 16092 bytes ago (1508 bytes ahead in playback buffer)
13:32:48 DEV pulseaudio[275035]: alsa_output.platform-rk809-sound.stereo-fallback: Found underrun 16156 bytes ago (1444 bytes ahead in playback buffer)
13:32:48 DEV pulseaudio[275035]: alsa_output.platform-rk809-sound.stereo-fallback: Found underrun 16188 bytes ago (1412 bytes ahead in playback buffer)
13:32:48 DEV pulseaudio[275035]: alsa_output.platform-rk809-sound.stereo-fallback: Found underrun 16252 bytes ago (1348 bytes ahead in playback buffer)
13:32:48 DEV pulseaudio[275035]: alsa_output.platform-rk809-sound.stereo-fallback: Found underrun 16284 bytes ago (1348 bytes ahead in playback buffer)
13:32:48 DEV pulseaudio[275035]: alsa_output.platform-rk809-sound.stereo-fallback: Found underrun 16340 bytes ago (1292 bytes ahead in playback buffer)
13:32:48 DEV pulseaudio[275035]: alsa_output.platform-rk809-sound.stereo-fallback: Found underrun 16372 bytes ago (1260 bytes ahead in playback buffer)
13:32:48 DEV pulseaudio[275035]: alsa_output.platform-rk809-sound.stereo-fallback: Found underrun 16468 bytes ago (1164 bytes ahead in playback buffer)
13:32:48 DEV pulseaudio[275035]: alsa_output.platform-rk809-sound.stereo-fallback: Found underrun 16500 bytes ago (1132 bytes ahead in playback buffer)
13:32:48 DEV pulseaudio[275035]: alsa_output.platform-rk809-sound.stereo-fallback: Found underrun 16564 bytes ago (1068 bytes ahead in playback buffer)
13:32:48 DEV pulseaudio[275035]: alsa_output.platform-rk809-sound.stereo-fallback: Found underrun 16596 bytes ago (1036 bytes ahead in playback buffer)
13:32:48 DEV pulseaudio[275035]: Sink alsa_output.platform-rk809-sound.stereo-fallback becomes idle, timeout in 5 seconds.
13:32:48 DEV pulseaudio[275035]: alsa_output.platform-rk809-sound.stereo-fallback: Found underrun 16660 bytes ago (972 bytes ahead in playback buffer)
13:32:48 DEV pulseaudio[275035]: Requested volume: front-left: 26214 / 40% / -23.88 dB, front-right: 26214 / 40% / -23.88 dB
13:32:48 DEV pulseaudio[275035]: Got hardware volume: front-left: 26241 / 40% / -23.85 dB, front-right: 26241 / 40% / -23.85 dB
13:32:48 DEV pulseaudio[275035]: Calculated software volume: front-left: 65469 / 100% / -0.03 dB, front-right: 65469 / 100% / -0.03 dB (accurate-enough=yes)
13:32:48 DEV pulseaudio[275035]: Volume not changing
13:32:48 DEV pulseaudio[275035]: Requested to rewind 17632 bytes.
13:32:48 DEV pulseaudio[275035]: Limited to 17312 bytes.
13:32:48 DEV pulseaudio[275035]: before: 4328
13:32:48 DEV pulseaudio[275035]: after: 4328
13:32:48 DEV pulseaudio[275035]: Rewound 17312 bytes.
13:32:48 DEV pulseaudio[275035]: Processing rewind...
13:32:48 DEV pulseaudio[275035]: latency = 1185
13:32:48 DEV pulseaudio[275035]: Processing rewind...
13:32:48 DEV pulseaudio[275035]: alsa_output.platform-rk809-sound.stereo-fallback: state: RUNNING -> IDLE
13:32:48 DEV pulseaudio[275035]: Sink alsa_output.platform-rk809-sound.stereo-fallback becomes idle, timeout in 5 seconds.
13:32:48 DEV pulseaudio[275035]: Hmm, no streams around, trying to vacuum.
13:32:48 DEV pulseaudio[275035]: Freeing input 1004305 "ALSA Playback"
13:32:48 DEV pulseaudio[275035]: Negotiated format: pcm, format.sample_format = ""float32le"" format.rate = "44100" format.channels = "2" format.channel_map = ""front-left,front-right""
13:32:48 DEV pulseaudio[275035]: Trying to change sample spec
13:32:48 DEV pulseaudio[275035]: Sink alsa_output.platform-rk809-sound.stereo-fallback becomes busy, resuming.
13:32:48 DEV pulseaudio[275035]: Sink alsa_output.platform-rk809-sound.stereo-fallback becomes idle, timeout in 5 seconds.
13:32:48 DEV pulseaudio[275035]: Forcing resampler 'copy', because of fixed, identical sample rates.
13:32:48 DEV pulseaudio[275035]: Resampler:
13:32:48 DEV pulseaudio[275035]: rate 44100 -> 44100 (method copy)
13:32:48 DEV pulseaudio[275035]: format float32le -> s16le (intermediate s16le)
13:32:48 DEV pulseaudio[275035]: channels 2 -> 2 (resampling 2)
13:32:48 DEV pulseaudio[275035]: memblockq requested: maxlength=33554432, tlength=0, base=4, prebuf=0, minreq=1 maxrewind=0
13:32:48 DEV pulseaudio[275035]: memblockq sanitized: maxlength=33554432, tlength=33554432, base=4, prebuf=0, minreq=4 maxrewind=0
13:32:48 DEV pulseaudio[275035]: Created input 1004306 "ALSA Playback" on alsa_output.platform-rk809-sound.stereo-fallback with sample spec float32le 2ch 44100Hz and channel map front-left,front-right
13:32:48 DEV pulseaudio[275035]: media.name = "ALSA Playback"
13:32:48 DEV pulseaudio[275035]: application.name = "ALSA plug-in [audioplayer]"
13:32:48 DEV pulseaudio[275035]: native-protocol.peer = "UNIX socket client"
13:32:48 DEV pulseaudio[275035]: native-protocol.version = "34"
13:32:48 DEV pulseaudio[275035]: application.process.id = "271089"
13:32:48 DEV pulseaudio[275035]: application.process.user = "echionaudioplayer"
13:32:48 DEV pulseaudio[275035]: application.process.host = "DEV"
13:32:48 DEV pulseaudio[275035]: application.process.binary = "audioplayer"
13:32:48 DEV pulseaudio[275035]: application.language = "C"
13:32:48 DEV pulseaudio[275035]: application.process.machine_id = "f00fd94949434ada8268f65b46c87927"
13:32:48 DEV pulseaudio[275035]: module-stream-restore.id = "sink-input-by-application-name:ALSA plug-in [audioplayer]"
13:32:48 DEV pulseaudio[275035]: Requested tlength=150.00 ms, minreq=10.00 ms
13:32:48 DEV pulseaudio[275035]: Early requests mode enabled, configuring sink latency to minreq.
13:32:48 DEV pulseaudio[275035]: Could not configure a sufficiently low latency. Early requests might not be satisfied.
13:32:48 DEV pulseaudio[275035]: Requested latency=10.00 ms, Received latency=99.95 ms
13:32:48 DEV pulseaudio[275035]: memblockq requested: maxlength=4194304, tlength=52920, base=8, prebuf=3528, minreq=3528 maxrewind=0
13:32:48 DEV pulseaudio[275035]: memblockq sanitized: maxlength=4194304, tlength=52920, base=8, prebuf=3528, minreq=3528 maxrewind=0
13:32:48 DEV pulseaudio[275035]: Final latency 249.95 ms = 130.00 ms + 2*10.00 ms + 99.95 ms
13:32:48 DEV pulseaudio[275035]: Requested volume: front-left: 26214 / 40% / -23.88 dB, front-right: 26214 / 40% / -23.88 dB
13:32:48 DEV pulseaudio[275035]: Got hardware volume: front-left: 26241 / 40% / -23.85 dB, front-right: 26241 / 40% / -23.85 dB
13:32:48 DEV pulseaudio[275035]: Calculated software volume: front-left: 65469 / 100% / -0.03 dB, front-right: 65469 / 100% / -0.03 dB (accurate-enough=yes)
13:32:48 DEV pulseaudio[275035]: Volume not changing
13:32:48 DEV pulseaudio[275035]: alsa_output.platform-rk809-sound.stereo-fallback: state: IDLE -> RUNNING
13:32:48 DEV pulseaudio[275035]: Requesting rewind due to end of underrun.
13:32:48 DEV pulseaudio[275035]: Requested to rewind 17632 bytes.
13:32:48 DEV pulseaudio[275035]: Limited to 17312 bytes.
13:32:48 DEV pulseaudio[275035]: before: 4328
13:32:48 DEV pulseaudio[275035]: after: 4328
13:32:48 DEV pulseaudio[275035]: Rewound 17312 bytes.
13:32:48 DEV pulseaudio[275035]: Processing rewind...
13:32:48 DEV pulseaudio[275035]: latency = 1237
13:32:48 DEV pulseaudio[275035]: Have to rewind 17312 bytes on render memblockq.
13:32:48 DEV pulseaudio[275035]: Processing rewind...
13:32:48 DEV pulseaudio[275035]: Implicit underrun of 'ALSA Playback'
13:32:48 DEV pulseaudio[275035]: alsa_output.platform-rk809-sound.stereo-fallback: Found underrun 15676 bytes ago (1924 bytes ahead in playback buffer)
13:32:48 DEV pulseaudio[275035]: alsa_output.platform-rk809-sound.stereo-fallback: Found underrun 15708 bytes ago (1924 bytes ahead in playback buffer)
13:32:48 DEV pulseaudio[275035]: alsa_output.platform-rk809-sound.stereo-fallback: Found underrun 15740 bytes ago (1892 bytes ahead in playback buffer)
13:32:48 DEV pulseaudio[275035]: alsa_output.platform-rk809-sound.stereo-fallback: Found underrun 15868 bytes ago (1764 bytes ahead in playback buffer)
13:32:48 DEV pulseaudio[275035]: alsa_output.platform-rk809-sound.stereo-fallback: Found underrun 15900 bytes ago (1732 bytes ahead in playback buffer)
13:32:48 DEV pulseaudio[275035]: alsa_output.platform-rk809-sound.stereo-fallback: Found underrun 16092 bytes ago (1508 bytes ahead in playback buffer)
13:32:48 DEV pulseaudio[275035]: alsa_output.platform-rk809-sound.stereo-fallback: Found underrun 16156 bytes ago (1476 bytes ahead in playback buffer)
13:32:48 DEV pulseaudio[275035]: alsa_output.platform-rk809-sound.stereo-fallback: Found underrun 16252 bytes ago (1380 bytes ahead in playback buffer)
13:32:48 DEV pulseaudio[275035]: alsa_output.platform-rk809-sound.stereo-fallback: Found underrun 16284 bytes ago (1348 bytes ahead in playback buffer)
13:32:48 DEV pulseaudio[275035]: alsa_output.platform-rk809-sound.stereo-fallback: Found underrun 16380 bytes ago (1252 bytes ahead in playback buffer)
13:32:48 DEV pulseaudio[275035]: alsa_output.platform-rk809-sound.stereo-fallback: Found underrun 16412 bytes ago (1220 bytes ahead in playback buffer)
13:32:48 DEV pulseaudio[275035]: alsa_output.platform-rk809-sound.stereo-fallback: Found underrun 16476 bytes ago (1156 bytes ahead in playback buffer)
13:32:48 DEV pulseaudio[275035]: alsa_output.platform-rk809-sound.stereo-fallback: Found underrun 16508 bytes ago (1124 bytes ahead in playback buffer)
13:32:48 DEV pulseaudio[275035]: alsa_output.platform-rk809-sound.stereo-fallback: Found underrun 16572 bytes ago (1060 bytes ahead in playback buffer)
13:32:48 DEV pulseaudio[275035]: alsa_output.platform-rk809-sound.stereo-fallback: Found underrun 16604 bytes ago (1028 bytes ahead in playback buffer)
13:32:48 DEV pulseaudio[275035]: alsa_output.platform-rk809-sound.stereo-fallback: Found underrun 16636 bytes ago (996 bytes ahead in playback buffer)
13:32:48 DEV pulseaudio[275035]: alsa_output.platform-rk809-sound.stereo-fallback: Found underrun 16668 bytes ago (964 bytes ahead in playback buffer)
13:32:48 DEV pulseaudio[275035]: alsa_output.platform-rk809-sound.stereo-fallback: Found underrun 16732 bytes ago (900 bytes ahead in playback buffer)
13:32:48 DEV pulseaudio[275035]: alsa_output.platform-rk809-sound.stereo-fallback: Found underrun 16732 bytes ago (900 bytes ahead in playback buffer)
13:32:48 DEV pulseaudio[275035]: Sink alsa_output.platform-rk809-sound.stereo-fallback becomes idle, timeout in 5 seconds.
13:32:48 DEV pulseaudio[275035]: alsa_output.platform-rk809-sound.stereo-fallback: Found underrun 16828 bytes ago (804 bytes ahead in playback buffer)
13:32:48 DEV pulseaudio[275035]: Requested volume: front-left: 26214 / 40% / -23.88 dB, front-right: 26214 / 40% / -23.88 dB
13:32:48 DEV pulseaudio[275035]: Got hardware volume: front-left: 26241 / 40% / -23.85 dB, front-right: 26241 / 40% / -23.85 dB
13:32:48 DEV pulseaudio[275035]: Calculated software volume: front-left: 65469 / 100% / -0.03 dB, front-right: 65469 / 100% / -0.03 dB (accurate-enough=yes)
13:32:48 DEV pulseaudio[275035]: Volume not changing
13:32:48 DEV pulseaudio[275035]: Requested to rewind 17632 bytes.
13:32:48 DEV pulseaudio[275035]: Limited to 17280 bytes.
13:32:48 DEV pulseaudio[275035]: before: 4320
13:32:48 DEV pulseaudio[275035]: after: 4320
13:32:48 DEV pulseaudio[275035]: Rewound 17280 bytes.
13:32:48 DEV pulseaudio[275035]: Processing rewind...
13:32:48 DEV pulseaudio[275035]: latency = 1303
13:32:48 DEV pulseaudio[275035]: Processing rewind...
13:32:48 DEV pulseaudio[275035]: alsa_output.platform-rk809-sound.stereo-fallback: state: RUNNING -> IDLE
13:32:48 DEV pulseaudio[275035]: Sink alsa_output.platform-rk809-sound.stereo-fallback becomes idle, timeout in 5 seconds.
13:32:48 DEV pulseaudio[275035]: Hmm, no streams around, trying to vacuum.
13:32:48 DEV pulseaudio[275035]: Freeing input 1004306 "ALSA Playback"
13:32:48 DEV pulseaudio[275035]: Negotiated format: pcm, format.sample_format = ""float32le"" format.rate = "44100" format.channels = "2" format.channel_map = ""front-left,front-right""
13:32:48 DEV pulseaudio[275035]: Trying to change sample spec
13:32:48 DEV pulseaudio[275035]: Sink alsa_output.platform-rk809-sound.stereo-fallback becomes busy, resuming.
13:32:48 DEV pulseaudio[275035]: Sink alsa_output.platform-rk809-sound.stereo-fallback becomes idle, timeout in 5 seconds.
13:32:48 DEV pulseaudio[275035]: Forcing resampler 'copy', because of fixed, identical sample rates.
13:32:48 DEV pulseaudio[275035]: Resampler:
13:32:48 DEV pulseaudio[275035]: rate 44100 -> 44100 (method copy)
13:32:48 DEV pulseaudio[275035]: format float32le -> s16le (intermediate s16le)
13:32:48 DEV pulseaudio[275035]: channels 2 -> 2 (resampling 2)
13:32:48 DEV pulseaudio[275035]: memblockq requested: maxlength=33554432, tlength=0, base=4, prebuf=0, minreq=1 maxrewind=0
13:32:48 DEV pulseaudio[275035]: memblockq sanitized: maxlength=33554432, tlength=33554432, base=4, prebuf=0, minreq=4 maxrewind=0
As you can see the sink is being freed and recreated repetitive. At this moment it already occured over 10 million times. Restarting the pulse audio daemon usually fixes this issue, but only for a few hours until it occurs again. But the time is also very random.
We use pulseaudio (Version 14.2) in system mode and as a systemd system deamon.
/etc/systemd/system/pulseaudio.service:
Click to expand
[Unit]
Description=PulseAudio system server
[Service]
Type=notify
ExecStart=/usr/bin/pulseaudio -vvvv --daemonize=no --high-priority --system --disallow-exit --no-cpu-limit --log-target=journal
ExecReload=/bin/kill -HUP
Restart=on-failure
Nice=-11
[Install]
WantedBy=multi-user.target
Also we tried several configuration (beside the default one) /etc/pulse/system.pa:
Click to expand
#!/usr/bin/pulseaudio -nF
Automatically restore the volume of streams and devices
load-module module-device-restore
load-module module-stream-restore
load-module module-card-restore
Automatically load driver modules depending on the hardware available
.ifexists module-udev-detect.so
#load-module module-udev-detect tsched=0
.else
Use the static hardware detection module (for systems that lack udev/hal support)
#load-module module-detect
.endif
Load several protocols
.ifexists module-esound-protocol-unix.so
load-module module-esound-protocol-unix
.endif
load-module module-native-protocol-unix
Automatically restore the default sink/source when changed by the user
during runtime
NOTE: This should be loaded as early as possible so that subsequent modules
that look up the default sink/source get the right value
load-module module-default-device-restore
Make sure we always have a sink around, even if it is a null sink.
load-module module-always-sink
Automatically suspend sinks/sources that become idle for too long
#load-module module-suspend-on-idle
#load-module module-alsa-card device_id=RK809 tsched=true tsched_buffer_size=1048576 tsched_buffer_watermark=262144
Enable positioned event sounds
load-module module-position-event-sounds
load-module module-alsa-card device_id=RK809 tsched=true tsched_buffer_size=1048576 tsched_buffer_watermark=262144
set-default-sink alsa_output.platform-rk809-sound.stereo-fallback
Disabling timer based sheduling didn't do anything. Also loading the card via load-module module-alsa-card, instead of using module-udev-detect (with tsched=0 and tsched=1), didn't fix it either.
We are currently testing working with these plattforms: Raxda Rockpi 3a Raspberry Pi Model 3 B+ Raxda Rockpi 4se
The Rockpi 4se works, but it has an dedicated sound chip (everest es8316) The Rockpi 3a uses the audio chip of the rk809 The raspberry pi Model 3 B+ uses the audio chip of the bcm2835 and also an usb sound card from sabrent which seems to be based on a c-media cm108 chip.
On the es8316 and the cm108 everything seems to work fine. But the rk809 and the bcm2835 cause the issue like seen above.
I saw that there is a similar issue: #126 But this thread didn't contain a solution for us.
If anybody has an idea what could cause this issue and maybe how to fix it, i would appreciate every advise. The only thing that we require is that pulseaudio has to run in system mode, because the application is also running after booting without any user being logged in. Enabling lingering didn't work for us.
Thank you