[pulseaudio-discuss] Cracks in the beginning of playback

[Hannu Lounento]

Hi,

I have a problem that sound played by a custom application using the ALSA API is
cracked for the first ca. 10 seconds.

I've reproduced the same problem with aplay: I'm playing a short (~19 seconds)
wav file and the first ~7 seconds of the playback is cracked / has gaps but
after that audio is played back properly, i.e. there are no noticeable cracks in
the playback.


Some observations I have made:

* pulseaudio reports a potential problem with the ALSA driver:

    E: [alsa-sink-HiFi sgtl5000-0] alsa-sink.c: ALSA woke us up to write new \
    data to the device, but there was actually nothing to write.

    E: [alsa-sink-HiFi sgtl5000-0] alsa-sink.c: Most likely this is a bug in \
    the ALSA driver '(null)'. Please report this issue to the ALSA developers.

    E: [alsa-sink-HiFi sgtl5000-0] alsa-sink.c: We were woken up with POLLOUT \
    set -- however a subsequent snd_pcm_avail() returned 0 or ano ther value < \
    min_avail.

* I can only reproduce the problem with pulseaudio. I.e. when I remove
  pulseaudio from the system playback is fine

* Re-nicing all the running pulseaudio threads to a nice value of -20 (adjusted
  using htop just before running aplay) does not have any impact on the observed
  behavior

* alsa-sink seems to suffer from underruns both in the beginning and end of the
  playback; my assumption is that these are not the cause of the cracks because
  underruns are not reported during playback when the audio is cracked

* alsa-sink monotonically increases the "minimal latency" during the
  problematic playback period starting with 1.00 ms and ending up close to 200
  ms; these log messages disappear when the playback stabilizes (or vice versa)

* Enabling shared ringbuffer support for module-native-protocol-unix
  as suggested related to a similar problem discussed at
  https://lists.freedesktop.org/archives/pulseaudio-discuss/2016-March/025795.html
  in default.pa

    load-module module-native-protocol-unix srbchannel=true

  did not have any impact on the observed behavior

* With DEBUG_TIMING enabled in alsa-sink.c, alsa-source.c, and rtpoll.c,
  pulseaudio reports significant deltas in expected sleep times, e.g.:

    D: [alsa-sink-HiFi sgtl5000-0] alsa-sink.c: Expected sleep: 106.62ms, real
    sleep: 0.88ms (diff -105.74 ms)

  but the deltas get significantly smaller shortly after the playback,
  presumably, starts.

  Log: https://www.dropbox.com/s/c6hvu6hi7rv4uye/pulseverbose.log.8?dl=0

  (I'm sorry for dropbox links but the log files were too big to be attached and
  my options for sharing files are very limited.)


My test cases:

1. With the default daemon configuration including

    ; default-sample-rate = 44100
    ; alternate-sample-rate = 48000
    ; default-sample-channels = 2
    ; default-channel-map = front-left,front-right

  by running

    $ time aplay /tmp/10-beeps.wav
    Playing WAVE '/tmp/10-beeps.wav' : Signed 16 bit Little Endian, Rate
    16000 Hz, Mono
    real    0m 20.28s
    user    0m 0.08s
    sys     0m 0.34s
 
  audio stabilizes after 10 seconds (what I described above).

  Log: https://www.dropbox.com/s/toz0a07l2gsi17u/pulseverbose.log?dl=0 


2. With modified configuration intended to match the output of our application
  and the format of the wav file

    default-sample-rate = 16000
    default-sample-channels = 1
    default-channel-map = mono

  audio does not stabilize at all but playback is cracked all the way until the
  end, and aplay prints out the following:

    $ time aplay /tmp/10-beeps.wav
    Playing WAVE '/tmp/10-beeps.wav' : Signed 16 bit Little Endian, Rate
    16000 Hz, Mono
    underrun!!! (at least 5968.392 ms long)
    underrun!!! (at least 12947.380 ms long)
    underrun!!! (at least 9962.868 ms long)
    underrun!!! (at least 1954.116 ms long)
    underrun!!! (at least 3955.021 ms long)
    real    0m 37.94s
    user    0m 0.12s
    sys     0m 0.52s

  This is probably a bad configuration as it makes the problem even worse. Even
  the aplay execution time is longer and the pulseaudio logs show multiple
  connections although aplay was only run once.

  Log: https://www.dropbox.com/s/53xm83jcxpmbq58/pulseverbose.log.2?dl=0


My configuration:

* pulseaudio 8.0 built with Yocto (krogoth, commit
  6c1c01392d91f512e2949ad1d57a75a8077478ba) containing the following patches on
  top of the upstream 8.0 release:

    Revert "module-switch-on-port-available: Route to preferred profile"
    alsa: set availability for (some) unavailable profiles
    card: move profile selection after pa_card_new()
    alsa, bluetooth: fail if user-requested profile doesn't exist
    card: add pa_card_profile.ports
    client-conf: Add allow-autospawn-for-root
    padsp: Make it compile on musl

* Default (daemon and client) configuration produced by the build (the Yocto
  recipe does not seem to do any changes, and by changing the configuration
  manually I have only been able to make the problem worse; see my observations
  above)

* pulseaudio run as a non-privileged user

* Verbose logs captured using

    -vvvv --log-target=newfile:/tmp/pulseverbose.log --log-time=1


I see two potential causes for the issue:

1. A bug in the ALSA driver like pulseaudio reported, or
2. A pulseaudio configuration problem

I'm not familiar enough with pulseaudio nor ALSA to reliably interpret the logs
and to decide what is the most probable cause to further investigate so I'd
appreciate any feedback regarding the problem.

Thanks,
-- 
-Hannu