Ubuntu
pulseaudio package

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

Bug #1284415 reported by Ricardo Salveti
6
This bug affects 1 person
Affects Status Importance Assigned to Milestone
android (Ubuntu)
Invalid
Undecided
Unassigned
pulseaudio (Ubuntu)
Fix Released
Undecided
Unassigned

Bug Description

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...

Revision history for this message
Ricardo Salveti (rsalveti) wrote :

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

Revision history for this message
Ricardo Salveti (rsalveti) wrote :

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...
....

Revision history for this message
David Henningsson (diwic) wrote : [PATCH] suspend-on-idle: Ensure we still time out if a stream remains corked

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

Revision history for this message
Launchpad Janitor (janitor) wrote :

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

Changed in pulseaudio (Ubuntu):
status: New → Fix Released
Ricardo Salveti (rsalveti)
Changed in android (Ubuntu):
status: New → Invalid
To post a comment you must log in.
This report contains Public information  
Everyone can see this information.
Subscribing...

Other bug subscribers

Remote bug watches

Bug watches keep track of this bug in other bug trackers.