Bug 50324 - pulseaudio continuously creates and frees input streams
Summary: pulseaudio continuously creates and frees input streams
Status: RESOLVED MOVED
Alias: None
Product: PulseAudio
Classification: Unclassified
Component: alsa (show other bugs)
Version: unspecified
Hardware: x86-64 (AMD64) Linux (All)
: medium normal
Assignee: pulseaudio-bugs
QA Contact: pulseaudio-bugs
URL:
Whiteboard:
Keywords:
Depends on:
Blocks:
 
Reported: 2012-05-24 14:51 UTC by Dennis Schridde
Modified: 2018-07-30 09:56 UTC (History)
6 users (show)

See Also:
i915 platform:
i915 features:


Attachments
chrome / flash log (19.95 KB, application/x-xz)
2012-05-25 02:32 UTC, Dennis Schridde
Details
don't starve log (145.17 KB, application/x-lzma)
2016-01-20 14:27 UTC, max ulidtko
Details
Pulse audio verbose log (1.00 MB, text/plain)
2016-02-14 21:04 UTC, Nick Wiltshire
Details

Description Dennis Schridde 2012-05-24 14:51:05 UTC
The following game is repeated over and over again, *lots* of times per second (Konsole has trouble printing as fast as the messages appear), which leads to 100% CPU usage in kmix and might also be responsible for the distorted sound I am experiencing:

D: [pulseaudio] module-suspend-on-idle.c: Sink alsa_output.pci-0000_00_06.1.analog-stereo becomes busy.
D: [pulseaudio] memblockq.c: memblockq requested: maxlength=33554432, tlength=0, base=4, prebuf=0, minreq=1 maxrewind=0
D: [pulseaudio] memblockq.c: memblockq sanitized: maxlength=33554432, tlength=33554432, base=4, prebuf=0, minreq=4 maxrewind=0
I: [pulseaudio] sink-input.c: Created input 1389 "ALSA Playback" on alsa_output.pci-0000_00_06.1.analog-stereo with sample spec s16le 2ch 44100Hz and channel map front-left,front-right
I: [pulseaudio] sink-input.c:     media.name = "ALSA Playback"
I: [pulseaudio] sink-input.c:     application.name = "ALSA plug-in [chrome]"
I: [pulseaudio] sink-input.c:     native-protocol.peer = "UNIX socket client"
I: [pulseaudio] sink-input.c:     native-protocol.version = "26"
I: [pulseaudio] sink-input.c:     application.process.id = "2912"
I: [pulseaudio] sink-input.c:     application.process.user = "UUU"
I: [pulseaudio] sink-input.c:     application.process.host = "HHH"
I: [pulseaudio] sink-input.c:     application.process.binary = "chrome"
I: [pulseaudio] sink-input.c:     application.icon_name = "google-chrome"
I: [pulseaudio] sink-input.c:     window.x11.display = ":0"
I: [pulseaudio] sink-input.c:     application.language = "en_GB.UTF-8"
I: [pulseaudio] sink-input.c:     application.process.machine_id = "da20799125212121ea1810b900000015"
I: [pulseaudio] sink-input.c:     application.process.session_id = "da20799125212121ea1810b900000015-1337888076.451378-629967621"
I: [pulseaudio] sink-input.c:     module-stream-restore.id = "sink-input-by-application-name:ALSA plug-in [chrome]"
I: [pulseaudio] protocol-native.c: Requested tlength=60.00 ms, minreq=14.99 ms
D: [pulseaudio] protocol-native.c: Early requests mode enabled, configuring sink latency to minreq.
D: [pulseaudio] protocol-native.c: Requested latency=14.99 ms, Received latency=100.14 ms
D: [pulseaudio] memblockq.c: memblockq requested: maxlength=4194304, tlength=52992, base=4, prebuf=7940, minreq=17660 maxrewind=0
D: [pulseaudio] memblockq.c: memblockq sanitized: maxlength=4194304, tlength=52992, base=4, prebuf=7940, minreq=17660 maxrewind=0
I: [pulseaudio] protocol-native.c: Final latency 400.54 ms = 100.18 ms + 2*100.11 ms + 100.14 ms
D: [alsa-sink] alsa-sink.c: Requested volume: 0: 100% 1: 100%
D: [alsa-sink] alsa-sink.c:            in dB: 0: 0.00 dB 1: 0.00 dB
D: [alsa-sink] alsa-sink.c: Got hardware volume: 0: 100% 1: 100%
D: [alsa-sink] alsa-sink.c:               in dB: 0: 0.00 dB 1: 0.00 dB
D: [alsa-sink] alsa-sink.c: Calculated software volume: 0: 100% 1: 100% (accurate-enough=yes)
D: [alsa-sink] alsa-sink.c:                      in dB: 0: 0.00 dB 1: 0.00 dB
D: [alsa-sink] sink.c: Volume not changing
D: [pulseaudio] protocol-dbus.c: Interface org.PulseAudio.Core1.Stream added for object /org/pulseaudio/core1/playback_stream1389
D: [alsa-sink] protocol-native.c: Requesting rewind due to end of underrun.
D: [alsa-sink] alsa-sink.c: Requested to rewind 17664 bytes.
D: [alsa-sink] alsa-sink.c: Limited to 17380 bytes.
D: [alsa-sink] alsa-sink.c: before: 4345
D: [alsa-sink] alsa-sink.c: after: 4345
D: [alsa-sink] alsa-sink.c: Rewound 17380 bytes.
D: [alsa-sink] sink.c: Processing rewind...
D: [alsa-sink] sink.c: latency = 1259
D: [alsa-sink] sink-input.c: Have to rewind 17380 bytes on render memblockq.
D: [alsa-sink] source.c: Processing rewind...
D: [alsa-sink] protocol-native.c: Underrun on 'ALSA Playback', 0 bytes in queue.
D: [alsa-sink] alsa-sink.c: Requested volume: 0: 100% 1: 100%
D: [alsa-sink] alsa-sink.c:            in dB: 0: 0.00 dB 1: 0.00 dB
D: [alsa-sink] alsa-sink.c: Got hardware volume: 0: 100% 1: 100%
D: [alsa-sink] alsa-sink.c:               in dB: 0: 0.00 dB 1: 0.00 dB
D: [alsa-sink] alsa-sink.c: Calculated software volume: 0: 100% 1: 100% (accurate-enough=yes)
D: [alsa-sink] alsa-sink.c:                      in dB: 0: 0.00 dB 1: 0.00 dB
D: [alsa-sink] sink.c: Volume not changing
D: [alsa-sink] alsa-sink.c: Requested to rewind 17664 bytes.
D: [alsa-sink] alsa-sink.c: Limited to 17340 bytes.
D: [alsa-sink] alsa-sink.c: before: 4335
D: [alsa-sink] alsa-sink.c: after: 4335
D: [alsa-sink] alsa-sink.c: Rewound 17340 bytes.
D: [alsa-sink] sink.c: Processing rewind...
D: [alsa-sink] sink.c: latency = 1354
D: [alsa-sink] source.c: Processing rewind...
D: [pulseaudio] module-suspend-on-idle.c: Sink alsa_output.pci-0000_00_06.1.analog-stereo becomes idle, timeout in 5 seconds.
D: [pulseaudio] module-suspend-on-idle.c: Sink alsa_output.pci-0000_00_06.1.analog-stereo becomes idle, timeout in 5 seconds.
D: [pulseaudio] core.c: Hmm, no streams around, trying to vacuum.
D: [pulseaudio] protocol-dbus.c: Interface org.PulseAudio.Core1.Stream removed from object /org/pulseaudio/core1/playback_stream1389
I: [pulseaudio] sink-input.c: Freeing input 1389 "ALSA Playback"
D: [pulseaudio] module-intended-roles.c: Not setting device for stream ALSA Playback, because it lacks role.
D: [pulseaudio] module-suspend-on-idle.c: Sink alsa_output.pci-0000_00_06.1.analog-stereo becomes busy.
D: [pulseaudio] memblockq.c: memblockq requested: maxlength=33554432, tlength=0, base=4, prebuf=0, minreq=1 maxrewind=0
D: [pulseaudio] memblockq.c: memblockq sanitized: maxlength=33554432, tlength=33554432, base=4, prebuf=0, minreq=4 maxrewind=0
I: [pulseaudio] sink-input.c: Created input 1390 "ALSA Playback" on alsa_output.pci-0000_00_06.1.analog-stereo with sample spec s16le 2ch 44100Hz and channel map front-left,front-right
[...]

Versions used are Gentoo/Linux kernel 3.4.0 and PulseAudio 2.0.
Audio device is:
00:06.1 Audio device: NVIDIA Corporation MCP55 High Definition Audio (rev a2)
        Subsystem: ASUSTeK Computer Inc. Device 81f6
        Kernel driver in use: snd_hda_intel
Comment 1 Dennis Schridde 2012-05-24 15:33:07 UTC
P.S: This is very likely a regression from 1.99.2 to 2.0 or is related to the kernel upgrade from 3.3.5 to 3.4.0.
Comment 2 Arun Raghavan 2012-05-24 19:19:03 UTC
I don't see where the stream is torn down. Does this only happen with Chrome? Also, please attach full server logs.
Comment 3 Dennis Schridde 2012-05-25 02:32:08 UTC
Created attachment 62093 [details]
chrome / flash log

(In reply to comment #2)
> I don't see where the stream is torn down. Does this only happen with Chrome?
It appears that it only happens with Flash. When Chrome plays a Youtube HTML5 video, the sound is not distorted. When Chrome plays the same video via the Flash player (after disabling the HTML5 trial), the sound is normal.

It also only happens with Flash version 11.2.31.144 which comes with Chrome as PepperFlash: /opt/google/chrome/PepperFlash/libpepflashplayer.so
Flash version 11.2.202.235, which is installed regularly as /opt/Adobe/flash-player/flash-plugin/libflashplayer.so does not show the issue.
(The presence of two Flash plugins was quite unexpected - I had to check chrome://plugins to figure it out and then disable the first.)

I assume this can be closed, unless you see something in the log that is suspicious.
Comment 4 Dennis Schridde 2012-12-10 18:58:03 UTC
This might have some relation to tsched=0, which I now found I had enabled in my /etc/pulse/default.pa (I don't remember when I did this - whether before or after I reported this bug). I removed tsched=0 and my Chrome PepperFlash sound distortion problem is gone.
Comment 5 Dennis Schridde 2012-12-10 19:10:39 UTC
I am now using:
Google Chrome 24.0.1312.35 beta
Pepper Flash 11.5.31.110
PulseAudio 2.99.3
Linux Kernel 3.6.8

After removing tsched=0, not only my Pepper Flash sound is without distortion, but also the pulseaudio server does not anymore output the piles of text mentioned in comment #0. Hence I close as works-for-me.
Comment 6 Dennis Schridde 2012-12-10 19:12:04 UTC
(In reply to comment #4)
> I removed tsched=0 and my Chrome PepperFlash sound distortion problem is gone.
(When I enabled tsched=0 again, the problem re-appears.)
Comment 7 Svein Ove Aas 2014-03-12 22:30:46 UTC
This exact problem is happening for me, specifically for Steam games on Gentoo.

It sometimes doesn't happen if I start the game as the first audio input of my session.

Other alsa inputs work.
Comment 8 Svein Ove Aas 2014-03-12 22:31:32 UTC
That's on both 4.0 and 5.0, by the way.
Comment 9 Raymond 2014-03-13 01:58:41 UTC
if chrome request 60ms buffer and 15ms period through always plugin 

can pulseaudio rewind 17664 bytes since pulseaudio need to wake-up  20ms before the 60 ms buffer is empty ?
Comment 10 Al Tobey 2014-04-15 23:10:11 UTC
Same issue here on PA 5.0 + Chromium + PepperFlash. What's weird is this used to work flawlessly on this machine and others. Other applications seem to be working fine, so it seems to be some interaction between PepperFlash and PA.

None of the settings I've tried, including tsched=0 have made the issue go away permanently. I'm running on a stock config again and it's still doing it.

$ pacman -Q chromium pulseaudio pulseaudio-alsa
chromium 34.0.1847.116-1
pulseaudio 5.0-1
pulseaudio-alsa 2-2
$ grep version /usr/lib/chromium/PepperFlash/manifest.json 
    "version": "12.0.0.70",
Comment 11 Al Tobey 2014-04-15 23:57:51 UTC
This looks relevant: https://code.google.com/p/chromium/issues/detail?id=32757#c75
Comment 12 Arun Raghavan 2014-04-16 06:30:04 UTC
(In reply to comment #11)
> This looks relevant:
> https://code.google.com/p/chromium/issues/detail?id=32757#c75

It is not, that is a very different bug.

It would be useful, again, to have verbose server logs to see what's happening (both while Steam is running, as well as separately with Chrome)
Comment 13 Dirk Thierbach 2014-06-08 13:27:32 UTC
I'm experiencing the same problem, not with Chrome (which I don't use), but with several ALSA clients. All Pulseaudio clients (including paplay) work. aplay also works for some reason; alsaplayer, timidity and mocp are not usable (sound is like what you get on fast forward). The -vvvv pulseaudio log looks very similar (extract for "alsaplayer" below).

This is on Debian/Sid, pulse packages version 5.0-2. It worked before, some upgrade (I didn't run into that problem immediately, so I don't know which one) broke it.

Please tell me if you need the full log, or other details.

(   7.600|   0.000) I: [pulseaudio] sink-input.c: Created input 0 "ALSA Playback" on alsa_output.usb-Roland_UA-25EX-00-UA25EX.analog-stereo with sa
mple spec s16le 2ch 44100Hz and channel map front-left,front-right
(   7.600|   0.000) I: [pulseaudio] sink-input.c:     media.name = "ALSA Playback"
(   7.600|   0.000) I: [pulseaudio] sink-input.c:     application.name = "ALSA plug-in [alsaplayer]"
(   7.600|   0.000) I: [pulseaudio] sink-input.c:     native-protocol.peer = "UNIX socket client"
(   7.600|   0.000) I: [pulseaudio] sink-input.c:     native-protocol.version = "29"
[...]
(   7.600|   0.000) I: [pulseaudio] sink-input.c:     module-stream-restore.id = "sink-input-by-application-name:ALSA plug-in [alsaplayer]"
(   7.600|   0.000) I: [pulseaudio] protocol-native.c: Requested tlength=185.76 ms, minreq=11.61 ms
(   7.600|   0.000) D: [pulseaudio] protocol-native.c: Early requests mode enabled, configuring sink latency to minreq.
(   7.600|   0.000) D: [pulseaudio] protocol-native.c: Requested latency=11.61 ms, Received latency=99.95 ms
(   7.600|   0.000) D: [pulseaudio] memblockq.c: memblockq requested: maxlength=4194304, tlength=52896, base=4, prebuf=2048, minreq=17628 maxrewind
=0
(   7.600|   0.000) D: [pulseaudio] memblockq.c: memblockq sanitized: maxlength=4194304, tlength=52896, base=4, prebuf=2048, minreq=17628 maxrewind
=0
(   7.600|   0.000) I: [pulseaudio] protocol-native.c: Final latency 399.82 ms = 100.00 ms + 2*99.93 ms + 99.95 ms
(   7.601|   0.000) D: [pulseaudio] core-subscribe.c: Dropped redundant event due to change event.
(   7.601|   0.000) D: [alsa-sink-USB Audio] alsa-sink.c: Requested to rewind 17632 bytes.
(   7.601|   0.000) D: [pulseaudio] module-suspend-on-idle.c: Sink alsa_output.usb-Roland_UA-25EX-00-UA25EX.analog-stereo becomes idle, timeout in 
5 seconds.
(   7.601|   0.000) D: [alsa-sink-USB Audio] alsa-sink.c: Limited to 17376 bytes.
(   7.601|   0.000) D: [alsa-sink-USB Audio] alsa-sink.c: before: 4344
(   7.601|   0.000) D: [alsa-sink-USB Audio] alsa-sink.c: after: 4344
(   7.601|   0.000) D: [alsa-sink-USB Audio] alsa-sink.c: Rewound 17376 bytes.
(   7.601|   0.000) D: [alsa-sink-USB Audio] sink.c: Processing rewind...
(   7.602|   0.000) D: [alsa-sink-USB Audio] source.c: Processing rewind...
(   7.602|   0.000) D: [pulseaudio] module-suspend-on-idle.c: Sink alsa_output.usb-Roland_UA-25EX-00-UA25EX.analog-stereo becomes idle, timeout in 
5 seconds.
(   7.602|   0.000) D: [pulseaudio] core.c: Hmm, no streams around, trying to vacuum.
(   7.602|   0.000) I: [pulseaudio] sink-input.c: Freeing input 0 "ALSA Playback"
(   7.602|   0.000) D: [pulseaudio] module-intended-roles.c: Not setting device for stream ALSA Playback, because it lacks role.
(   7.602|   0.000) D: [pulseaudio] sink-input.c: Negotiated format: pcm, format.sample_format = "\"s16le\""  format.rate = "44100"  format.channels = "2"  format.channel_map = "\"front-left,front-right\""
(   7.602|   0.000) D: [pulseaudio] module-suspend-on-idle.c: Sink alsa_output.usb-Roland_UA-25EX-00-UA25EX.analog-stereo becomes busy, resuming.
(   7.602|   0.000) D: [pulseaudio] module-suspend-on-idle.c: Sink alsa_output.usb-Roland_UA-25EX-00-UA25EX.analog-stereo becomes idle, timeout in 5 seconds.
(   7.602|   0.000) D: [pulseaudio] memblockq.c: memblockq requested: maxlength=33554432, tlength=0, base=4, prebuf=0, minreq=1 maxrewind=0
(   7.602|   0.000) D: [pulseaudio] memblockq.c: memblockq sanitized: maxlength=33554432, tlength=33554432, base=4, prebuf=0, minreq=4 maxrewind=0
(   7.602|   0.000) I: [pulseaudio] sink-input.c: Created input 1 "ALSA Playback" on alsa_output.usb-Roland_UA-25EX-00-UA25EX.analog-stereo with sample spec s16le 2ch 44100Hz and channel map front-left,front-right

and so on from there on.
Comment 14 Raymond 2014-06-08 14:36:07 UTC
I: [pulseaudio] protocol-native.c: Requested tlength=60.00 ms, minreq=14.99 ms

60ms*44100Hz = 2646 samples

but 1/4 is 661.5 samples which is incorrect
Comment 15 max ulidtko 2016-01-20 14:27:34 UTC
Created attachment 121153 [details]
don't starve log
Comment 16 max ulidtko 2016-01-20 14:35:42 UTC
I'm seeing exact same behaviour with the game Don't Starve from Steam.

The resulting choppy sound is fiendishly annoying.

I also note that the freeing/creating loop doesn't roll 100% of the time: sometimes the sound is smooth (PA log is still at these times) for minutes. It seems that CPU usage spikes trigger this malfunction.

Is there any workaround for this bug, or anything at all that could be done to obtain clean sound 100% of the time?
Comment 17 Arun Raghavan 2016-01-21 03:16:21 UTC
(In reply to Raymond from comment #14)
> I: [pulseaudio] protocol-native.c: Requested tlength=60.00 ms, minreq=14.99
> ms
> 
> 60ms*44100Hz = 2646 samples
> 
> but 1/4 is 661.5 samples which is incorrect

Which is why you see 14.99 ms as the minreq, rounding down.
Comment 18 Arun Raghavan 2016-01-21 03:17:50 UTC
I see multiple issues being reported here, please let's not conflate them.

One problem is related to choppy output on USB devices, related to timer-based scheduling. That might be fixed in the soon-to-be-release PulseAudio 8.0.

The second is about choppy output, for this, please open a separate bug, with alsa-info and full server logs on a recent PulseAudio version. I'm not seeing these sorts of issues on Steam myself.

The third, which is the original problem of continuously created/freed streams -- is someone still seeing this? If yes, again -- full server logs please.
Comment 19 max ulidtko 2016-01-22 07:33:34 UTC
(In reply to Arun Raghavan from comment #18)
> The third, which is the original problem of continuously created/freed
> streams -- is someone still seeing this? If yes, again -- full server logs
> please.

Yes. This happens to me in Don't Starve and other games. Find full server log attached above.
Comment 20 Nick Wiltshire 2016-02-14 21:04:42 UTC
Created attachment 121751 [details]
Pulse audio verbose log

Here's my pulse log. Things of note:

You'll see in the first part of the log me opening and closing both mumble and don't starve while trying to get it to glitch.

The glitch comes and goes during play, and may or may not have to do with mumble, but "feels" like it is more prevalent with mumble running.

The actual glitch starts at 125.4. I wanted to get it to come and go while the log was running, but the log quickly reached multiple gigs so I truncated it to 1M before posting

I see a lot of buffer underruns, may be related.

This only seems to happen with this game on my system.
Comment 21 GitLab Migration User 2018-07-30 09:56:15 UTC
-- GitLab Migration Automatic Message --

This bug has been migrated to freedesktop.org's GitLab instance and has been closed from further activity.

You can subscribe and participate further through the new bug through this link to our GitLab instance: https://gitlab.freedesktop.org/pulseaudio/pulseaudio/issues/126.


Use of freedesktop.org services, including Bugzilla, is subject to our Code of Conduct. How we collect and use information is described in our Privacy Policy.