Alsa waking up pulseaudio too frequently on Mako (Nexus 4)

[Ricardo Salveti]

current build number: 206
device name: mako
channel: trusty-proposed
last update: 2014-02-25 02:02:15
version version: 206
version ubuntu: 20140224
version device: 20140224

Just boot the image with mako, enable debug loglevel in pulse, and you can easily see alsa waking up pulse quite frequently after maliit-server is started.

Feb 25 02:54:03 ubuntu-phablet pulseaudio[1881]: [pulseaudio] module-suspend-on-idle.c: Sink alsa_output.platform-soc-audio.0.HiFi__hw_apq8064tablasnd_0__sink becomes idle, timeout in 5 seconds.
Feb 25 02:54:03 ubuntu-phablet pulseaudio[1881]: [pulseaudio] core.c: Hmm, no streams around, trying to vacuum.
Feb 25 02:54:03 ubuntu-phablet pulseaudio[1881]: [pulseaudio] sink-input.c: Freeing input 0 "pulsesink probe"
Feb 25 02:54:03 ubuntu-phablet pulseaudio[1881]: [pulseaudio] module-intended-roles.c: Not setting device for stream Playback Stream, because it lacks role.
Feb 25 02:54:03 ubuntu-phablet pulseaudio[1881]: [pulseaudio] module-suspend-on-idle.c: Sink alsa_output.platform-soc-audio.0.HiFi__hw_apq8064tablasnd_0__sink becomes busy, resuming.
Feb 25 02:54:03 ubuntu-phablet pulseaudio[1881]: [pulseaudio] memblockq.c: memblockq requested: maxlength=33554432, tlength=0, base=4, prebuf=0, minreq=1 maxrewind=0
Feb 25 02:54:03 ubuntu-phablet pulseaudio[1881]: [pulseaudio] memblockq.c: memblockq sanitized: maxlength=33554432, tlength=33554432, base=4, prebuf=0, minreq=4 maxrewind=0
Feb 25 02:54:03 ubuntu-phablet pulseaudio[1881]: [pulseaudio] sink-input.c: Created input 1 "Playback Stream" on alsa_output.platform-soc-audio.0.HiFi__hw_apq8064tablasnd_0__sink with sample spec s16le 2ch 44100Hz and channel map front-left,front-right
Feb 25 02:54:03 ubuntu-phablet pulseaudio[1881]: [pulseaudio] sink-input.c: media.name = "Playback Stream"
Feb 25 02:54:03 ubuntu-phablet pulseaudio[1881]: [pulseaudio] sink-input.c: application.name = "maliit-server"
Feb 25 02:54:03 ubuntu-phablet pulseaudio[1881]: [pulseaudio] sink-input.c: native-protocol.peer = "UNIX socket client"
Feb 25 02:54:03 ubuntu-phablet pulseaudio[1881]: [pulseaudio] sink-input.c: native-protocol.version = "28"
Feb 25 02:54:03 ubuntu-phablet pulseaudio[1881]: [pulseaudio] sink-input.c: application.process.id = "1989"
Feb 25 02:54:03 ubuntu-phablet pulseaudio[1881]: [pulseaudio] sink-input.c: application.process.user = "phablet"
Feb 25 02:54:03 ubuntu-phablet pulseaudio[1881]: [pulseaudio] sink-input.c: application.process.host = "ubuntu-phablet"
Feb 25 02:54:03 ubuntu-phablet pulseaudio[1881]: [pulseaudio] sink-input.c: application.process.binary = "maliit-server"
Feb 25 02:54:03 ubuntu-phablet pulseaudio[1881]: [pulseaudio] sink-input.c: application.language = "en_US.UTF-8"
Feb 25 02:54:03 ubuntu-phablet pulseaudio[1881]: [pulseaudio] sink-input.c: application.process.machine_id = "a5b3df3acc0eac7140e720c4530bf9b3"
Feb 25 02:54:03 ubuntu-phablet pulseaudio[1881]: [pulseaudio] sink-input.c: application.process.session_id = "c1"
Feb 25 02:54:03 ubuntu-phablet pulseaudio[1881]: [pulseaudio] sink-input.c: module-stream-restore.id = "sink-input-by-application-name:maliit-server"
Feb 25 02:54:03 ubuntu-phablet pulseaudio[1881]: [pulseaudio] protocol-native.c: Requested tlength=200.00 ms, minreq=10.00 ms
Feb 25 02:54:03 ubuntu-phablet pulseaudio[1881]: [pulseaudio] protocol-native.c: Adjust latency mode enabled, configuring sink latency to half of overall latency.
Feb 25 02:54:03 ubuntu-phablet pulseaudio[1881]: [pulseaudio] protocol-native.c: Requested latency=90.00 ms, Received latency=90.00 ms
Feb 25 02:54:03 ubuntu-phablet pulseaudio[1881]: [pulseaudio] memblockq.c: memblockq requested: maxlength=4194304, tlength=19404, base=4, prebuf=0, minreq=1764 maxrewind=0
Feb 25 02:54:03 ubuntu-phablet pulseaudio[1881]: [pulseaudio] memblockq.c: memblockq sanitized: maxlength=4194304, tlength=19404, base=4, prebuf=0, minreq=1764 maxrewind=0
Feb 25 02:54:03 ubuntu-phablet pulseaudio[1881]: [pulseaudio] protocol-native.c: Final latency 200.00 ms = 90.00 ms + 2*10.00 ms + 90.00 ms
Feb 25 02:54:03 ubuntu-phablet pulseaudio[1881]: [alsa-sink-MultiMedia1 (*)] alsa-sink.c: Latency set to 90.00ms
Feb 25 02:54:03 ubuntu-phablet pulseaudio[1881]: [alsa-sink-MultiMedia1 (*)] alsa-sink.c: hwbuf_unused=16892
Feb 25 02:54:03 ubuntu-phablet pulseaudio[1881]: [alsa-sink-MultiMedia1 (*)] alsa-sink.c: setting avail_min=7311
Feb 25 02:54:03 ubuntu-phablet pulseaudio[1881]: [alsa-sink-MultiMedia1 (*)] alsa-sink.c: Requesting rewind due to latency change.
Feb 25 02:54:03 ubuntu-phablet pulseaudio[1881]: [alsa-sink-MultiMedia1 (*)] alsa-sink.c: Requested to rewind 32768 bytes.
Feb 25 02:54:03 ubuntu-phablet pulseaudio[1881]: [alsa-sink-MultiMedia1 (*)] alsa-sink.c: Limited to 28416 bytes.
Feb 25 02:54:03 ubuntu-phablet pulseaudio[1881]: [alsa-sink-MultiMedia1 (*)] alsa-sink.c: before: 7104
Feb 25 02:54:03 ubuntu-phablet pulseaudio[1881]: [alsa-sink-MultiMedia1 (*)] alsa-sink.c: after: 7104
Feb 25 02:54:03 ubuntu-phablet pulseaudio[1881]: [alsa-sink-MultiMedia1 (*)] alsa-sink.c: Rewound 28416 bytes.
Feb 25 02:54:03 ubuntu-phablet pulseaudio[1881]: [alsa-sink-MultiMedia1 (*)] sink.c: Processing rewind...
Feb 25 02:54:03 ubuntu-phablet pulseaudio[1881]: [alsa-sink-MultiMedia1 (*)] sink-input.c: Have to rewind 28416 bytes on render memblockq.
Feb 25 02:54:03 ubuntu-phablet pulseaudio[1881]: [alsa-sink-MultiMedia1 (*)] source.c: Processing rewind...
Feb 25 02:54:08 ubuntu-phablet pulseaudio[1881]: [alsa-sink-MultiMedia1 (*)] alsa-sink.c: Wakeup from ALSA!
Feb 25 02:54:08 ubuntu-phablet pulseaudio[1881]: [alsa-sink-MultiMedia1 (*)] alsa-sink.c: Underrun!
Feb 25 02:54:08 ubuntu-phablet pulseaudio[1881]: [alsa-sink-MultiMedia1 (*)] alsa-sink.c: Increasing wakeup watermark to 30.00 ms
Feb 25 02:54:09 ubuntu-phablet pulseaudio[1881]: [alsa-sink-MultiMedia1 (*)] alsa-sink.c: Scheduling delay of 10.12ms > 5.29ms, you might want to investigate this to improve latency...
Feb 25 02:54:09 ubuntu-phablet pulseaudio[1881]: [alsa-sink-MultiMedia1 (*)] alsa-sink.c: Scheduling delay of 28.64ms > 5.29ms, you might want to investigate this to improve latency...
Feb 25 02:54:09 ubuntu-phablet pulseaudio[1881]: [alsa-sink-MultiMedia1 (*)] alsa-sink.c: Wakeup from ALSA!
Feb 25 02:54:09 ubuntu-phablet pulseaudio[1881]: [alsa-sink-MultiMedia1 (*)] alsa-sink.c: Underrun!
Feb 25 02:54:09 ubuntu-phablet pulseaudio[1881]: [alsa-sink-MultiMedia1 (*)] alsa-sink.c: Increasing wakeup watermark to 40.00 ms
Feb 25 02:54:12 ubuntu-phablet pulseaudio[1881]: [alsa-sink-MultiMedia1 (*)] alsa-sink.c: Scheduling delay of 7.32ms > 7.06ms, you might want to investigate this to improve latency...
Feb 25 02:54:15 ubuntu-phablet pulseaudio[1881]: [alsa-sink-MultiMedia1 (*)] alsa-sink.c: Scheduling delay of 8.29ms > 7.06ms, you might want to investigate this to improve latency...
Feb 25 02:54:15 ubuntu-phablet pulseaudio[1881]: [alsa-sink-MultiMedia1 (*)] alsa-sink.c: Scheduling delay of 9.58ms > 7.06ms, you might want to investigate this to improve latency...
Feb 25 02:54:16 ubuntu-phablet pulseaudio[1881]: [alsa-sink-MultiMedia1 (*)] alsa-sink.c: Scheduling delay of 7.22ms > 7.06ms, you might want to investigate this to improve latency...
Feb 25 02:54:17 ubuntu-phablet pulseaudio[1881]: [alsa-sink-MultiMedia1 (*)] alsa-sink.c: Scheduling delay of 16.52ms > 7.06ms, you might want to investigate this to improve latency...
Feb 25 02:54:20 ubuntu-phablet pulseaudio[1881]: [alsa-sink-MultiMedia1 (*)] alsa-sink.c: Scheduling delay of 33.39ms > 7.06ms, you might want to investigate this to improve latency...
Feb 25 02:54:20 ubuntu-phablet pulseaudio[1881]: [alsa-sink-MultiMedia1 (*)] alsa-sink.c: Wakeup from ALSA!
Feb 25 02:54:20 ubuntu-phablet pulseaudio[1881]: [alsa-sink-MultiMedia1 (*)] alsa-sink.c: Underrun!
Feb 25 02:54:20 ubuntu-phablet pulseaudio[1881]: [alsa-sink-MultiMedia1 (*)] alsa-sink.c: Increasing wakeup watermark to 50.00 ms
Feb 25 02:54:21 ubuntu-phablet pulseaudio[1881]: [alsa-sink-MultiMedia1 (*)] alsa-sink.c: Scheduling delay of 15.64ms > 8.82ms, you might want to investigate this to improve latency...
Feb 25 02:54:28 ubuntu-phablet pulseaudio[1881]: [alsa-sink-MultiMedia1 (*)] alsa-sink.c: Scheduling delay of 13.22ms > 8.82ms, you might want to investigate this to improve latency...
Feb 25 02:54:31 ubuntu-phablet pulseaudio[1881]: [alsa-sink-MultiMedia1 (*)] alsa-sink.c: Scheduling delay of 13.13ms > 8.82ms, you might want to investigate this to improve latency...
Feb 25 02:54:36 ubuntu-phablet pulseaudio[1881]: [alsa-sink-MultiMedia1 (*)] alsa-sink.c: Scheduling delay of 18.05ms > 8.82ms, you might want to investigate this to improve latency...
Feb 25 02:54:41 ubuntu-phablet pulseaudio[1881]: [alsa-sink-MultiMedia1 (*)] alsa-sink.c: Scheduling delay of 11.24ms > 8.82ms, you might want to investigate this to improve latency...
Feb 25 02:54:41 ubuntu-phablet pulseaudio[1881]: [alsa-sink-MultiMedia1 (*)] alsa-sink.c: Scheduling delay of 14.47ms > 8.82ms, you might want to investigate this to improve latency...
Feb 25 02:54:44 ubuntu-phablet pulseaudio[1881]: [alsa-sink-MultiMedia1 (*)] alsa-sink.c: Scheduling delay of 24.64ms > 8.82ms, you might want to investigate this to improve latency...
Feb 25 02:54:44 ubuntu-phablet pulseaudio[1881]: [alsa-sink-MultiMedia1 (*)] alsa-sink.c: Scheduling delay of 9.07ms > 8.82ms, you might want to investigate this to improve latency...
Feb 25 02:54:47 ubuntu-phablet pulseaudio[1881]: [alsa-sink-MultiMedia1 (*)] alsa-sink.c: Scheduling delay of 13.65ms > 8.82ms, you might want to investigate this to improve latency...
....
Feb 25 02:55:00 ubuntu-phablet pulseaudio[1881]: [alsa-sink-MultiMedia1 (*)] alsa-sink.c: Scheduling delay of 9.31ms > 8.82ms, you might want to investigate this to improve latency...
Feb 25 02:55:19 ubuntu-phablet pulseaudio[1881]: [alsa-sink-MultiMedia1 (*)] alsa-sink.c: Scheduling delay of 13.60ms > 8.82ms, you might want to investigate this to improve latency...
Feb 25 02:55:30 ubuntu-phablet pulseaudio[1881]: [alsa-sink-MultiMedia1 (*)] alsa-sink.c: Scheduling delay of 12.89ms > 8.82ms, you might want to investigate this to improve latency...

[Ricardo Salveti (rsalveti)]

Pulseaudio continuously use ~2% of the cpu on mako.

perf's top output:
     2.28% libpulsecommon-4.0.so [.] __udivsi3
     1.86% libpulsecommon-4.0.so [.] __gnu_uldivmod_helper
     1.80% libasound.so.2.0.0 [.] snd_pcm_status_get_avail
     1.58% libpulsecommon-4.0.so [.] pa_hashmap_iterate
     0.98% libpulsecore-4.0.so [.] flush_postq
     0.89% libpulsecore-4.0.so [.] pa_asyncmsgq_read_after_poll
     0.79% libpulsecommon-4.0.so [.] __aeabi_uldivmod

[Ricardo Salveti (rsalveti)]

Also the following, from time to time:
Feb 24 15:30:46 ubuntu-phablet pulseaudio[1903]: [alsa-sink-MultiMedia1 (*)] alsa-sink.c: Scheduling delay of 26.92ms > 14.11ms, you might want to investigate this to improve latency...
Feb 24 15:30:47 ubuntu-phablet pulseaudio[1903]: [alsa-sink-MultiMedia1 (*)] ratelimit.c: 203 events suppressed
Feb 24 15:30:47 ubuntu-phablet pulseaudio[1903]: [alsa-sink-MultiMedia1 (*)] alsa-sink.c: Wakeup from ALSA!
Feb 24 15:30:47 ubuntu-phablet pulseaudio[1903]: message repeated 10 times: [ [alsa-sink-MultiMedia1 (*)] alsa-sink.c: Wakeup from ALSA!]
Feb 24 15:30:48 ubuntu-phablet pulseaudio[1903]: [alsa-sink-MultiMedia1 (*)] alsa-sink.c: ALSA woke us up to write new data to the device, but there was actually nothing to write!
Feb 24 15:30:48 ubuntu-phablet pulseaudio[1903]: [alsa-sink-MultiMedia1 (*)] alsa-sink.c: Most likely this is a bug in the ALSA driver '(null)'. Please report this issue to the ALSA developers.
Feb 24 15:30:48 ubuntu-phablet pulseaudio[1903]: [alsa-sink-MultiMedia1 (*)] alsa-sink.c: We were woken up with POLLOUT set -- however a subsequent snd_pcm_avail() returned 0 or another value < min_avail.
Feb 24 15:30:52 ubuntu-phablet pulseaudio[1903]: [alsa-sink-MultiMedia1 (*)] alsa-sink.c: Scheduling delay of 32.41ms > 14.11ms, you might want to investigate this to improve latency...
Feb 24 15:30:52 ubuntu-phablet pulseaudio[1903]: [alsa-sink-MultiMedia1 (*)] ratelimit.c: 205 events suppressed
Feb 24 15:30:52 ubuntu-phablet pulseaudio[1903]: [alsa-sink-MultiMedia1 (*)] alsa-sink.c: Wakeup from ALSA!
Feb 24 15:30:54 ubuntu-phablet pulseaudio[1903]: [alsa-sink-MultiMedia1 (*)] alsa-sink.c: Scheduling delay of 21.88ms > 14.11ms, you might want to investigate this to improve latency...
Feb 24 15:30:54 ubuntu-phablet pulseaudio[1903]: [alsa-sink-MultiMedia1 (*)] alsa-sink.c: Scheduling delay of 22.75ms > 14.11ms, you might want to investigate this to improve latency...
Feb 24 15:30:55 ubuntu-phablet pulseaudio[1903]: [alsa-sink-MultiMedia1 (*)] alsa-sink.c: Scheduling delay of 16.65ms > 14.11ms, you might want to investigate this to improve latency...
....

[David Henningsson (diwic)]

If a stream is started corked and remains corked, the sink/source
remained idle without being properly suspended. This patch fixes
that issue.

BugLink: https://bugs.launchpad.net/bugs/1284415
Tested-by: Ricardo Salveti <email address hidden>
Signed-off-by: David Henningsson <email address hidden>
---
 src/modules/module-suspend-on-idle.c | 13 ++++++++++---
 1 file changed, 10 insertions(+), 3 deletions(-)

diff --git a/src/modules/module-suspend-on-idle.c b/src/modules/module-suspend-on-idle.c
index 0585e51..a4f90e0 100644
--- a/src/modules/module-suspend-on-idle.c
+++ b/src/modules/module-suspend-on-idle.c
@@ -141,10 +141,14 @@ static pa_hook_result_t sink_input_fixate_hook_cb(pa_core *c, pa_sink_input_new_

     /* We need to resume the audio device here even for
      * PA_SINK_INPUT_START_CORKED, since we need the device parameters
- * to be fully available while the stream is set up. */
+ * to be fully available while the stream is set up. In that case,
+ * make sure we close the sink again after the timeout interval. */

- if ((d = pa_hashmap_get(u->device_infos, data->sink)))
+ if ((d = pa_hashmap_get(u->device_infos, data->sink))) {
         resume(d);
+ if (d->sink && pa_sink_check_suspend(d->sink) <= 0)
+ restart(d);
+ }

     return PA_HOOK_OK;
 }
@@ -161,8 +165,11 @@ static pa_hook_result_t source_output_fixate_hook_cb(pa_core *c, pa_source_outpu
     else
         d = pa_hashmap_get(u->device_infos, data->source);

- if (d)
+ if (d) {
         resume(d);
+ if (d->source && pa_source_check_suspend(d->source) <= 0)
+ restart(d);
+ }

     return PA_HOOK_OK;
 }
--
1.7.9.5

[Launchpad Janitor (janitor)]

This bug was fixed in the package pulseaudio - 1:4.0-0ubuntu9

---------------
pulseaudio (1:4.0-0ubuntu9) trusty; urgency=medium

  * 0205-suspend-on-idle-ensure-we-still-time-out-if-a-stream-remains-corked.patch:
    - Properly suspending sink/source if the stream started corked and remains
      corked (LP: #1284415)
 -- Ricardo Salveti de Araujo <email address hidden> Tue, 25 Feb 2014 16:37:26 -0300