[alsa-devel] hw_ptr accuracy with intel8x0 -> PulseAudio issue

[Raymond Yau]

2009/12/2 pl bossart <bossart.nospam at gmail.com>

> Hi,
> I have been having issues for a while now with PulseAudio running on
> an older Thinkpad X41. PulseAudio relies on snd_pcm_avail() to detect
> underflows and increases the timer watermark when they happen. There
> are actually no audible underflows though...
> So I instrumented both PulseAudio (enabling DEBUG_TIMING in the
> alsa-sink.c code) and the kernel (latest alsa-kernel git) by adding
> the following printk  in pcm.h:
>
> static inline snd_pcm_uframes_t snd_pcm_playback_avail(struct
> snd_pcm_runtime *runtime)
> {
>        snd_pcm_sframes_t avail = runtime->status->hw_ptr +
> runtime->buffer_size - runtime->control->appl_ptr;
>        if (avail < 0)
>                avail += runtime->boundary;
>        else if ((snd_pcm_uframes_t) avail >= runtime->boundary)
>                avail -= runtime->boundary;
>        //plb
>        if(avail > runtime->buffer_size) {
>            snd_printk(KERN_ERR "avail %d hw_ptr %d buffer %d appl_ptr %d
> \n",
>                       avail, runtime->status->hw_ptr,
> runtime->buffer_size, runtime->control->appl_ptr);
>        }
>        return avail;
> }
>
> In my tests this error condition where avail is larger than the ring
> buffer happens fairly often. The dmesg log show messages such as
> [  834.524479] ALSA include/sound/pcm.h:600: avail 16403 hw_ptr 24351
> buffer 16384 appl_ptr 24332
> [  835.266937] ALSA include/sound/pcm.h:600: avail 16407 hw_ptr 55841
> buffer 16384 appl_ptr 55818
> and these messages are correlated with the times when PulseAudio
> detects underflows.
> The full log can be found at http://pastebin.com/f210aa108.
>
> I believe the issue is the accuracy of the hw_ptr reported by
> snd_intel8x0_pcm_pointer. If indeed such a condition occurred, it
> should be flagged as underflow, shouldn't it? There's been some
> changes in this part of the code to avoid extremely large values, here
> the issue seems more subtle, the pointer is only slightly off in most
> cases. This does screw-up PulseAudio though, the timer watermark keeps
> increasing and low-latency isn't possible.
>
> I'd be more than happy to run more experiments, however I have no idea
> what the hardware does to report the position of the hw pointer.
> Thanks for your feedback
> - Pierre
>
>

I: main.c: This is PulseAudio 0.9.21-296-gd2ab2


   1. D: alsa-util.c: Trying front:0 with SND_PCM_NO_AUTO_FORMAT ...
   2. D: alsa-util.c: Managed to open front:0
   3. D: alsa-util.c: Maximum hw buffer size is 371 ms
   4. D: alsa-util.c: Set buffer size first (to 4408 samples), period size
   second (to 1102 samples)

What is the purpose of these buffer-size and period size during the probing
phase  ?
The PA server seem use different values



   1. I: sink.c: Created sink 0 "alsa_output.pci-0000_00_1e.2.analog-stereo"
   with sample spec s16le 2ch 44100Hz and channel map front-left,front-right
   2. I: sink.c:     alsa.resolution_bits = "16"
   3. I: sink.c:     device.api = "alsa"
   4. I: sink.c:     device.class = "sound"
   5. I: sink.c:     alsa.class = "generic"
   6. I: sink.c:     alsa.subclass = "generic-mix"
   7. I: sink.c:     alsa.name = "Intel ICH6"
   8. I: sink.c:     alsa.id = "Intel ICH"
   9. I: sink.c:     alsa.subdevice = "0"
   10. I: sink.c:     alsa.subdevice_name = "subdevice #0"
   11. I: sink.c:     alsa.device = "0"
   12. I: sink.c:     alsa.card = "0"
   13. I: sink.c:     alsa.card_name = "Intel ICH6"
   14. I: sink.c:     alsa.long_card_name = "Intel ICH6 with AD1981B at irq
   22"
   15. I: sink.c:     alsa.driver_name = "snd_intel8x0"
   16. I: sink.c:     device.bus_path = "pci-0000:00:1e.2"
   17. I: sink.c:     sysfs.path =
   "/devices/pci0000:00/0000:00:1e.2/sound/card0"
   18. I: sink.c:     device.bus = "pci"
   19. I: sink.c:     device.vendor.id = "8086"
   20. I: sink.c:     device.vendor.name = "Intel Corporation"
   21. I: sink.c:     device.product.id = "266e"
   22. I: sink.c:     device.product.name = "82801FB/FBM/FR/FW/FRW (ICH6
   Family) AC'97 Audio Controller"
   23. I: sink.c:     device.form_factor = "internal"
   24. I: sink.c:     hal.udi =
   "/org/freedesktop/Hal/devices/pci_8086_266e_sound_card_0"
   25. I: sink.c:     hal.product = "Intel ICH6 with AD1981B Sound Card"
   26. I: sink.c:     hal.card_id = "Intel ICH6 with AD1981B"
   27. I: sink.c:     device.string = "front:0"
   28. I: sink.c:     device.buffering.buffer_size = "65536"
   29. I: sink.c:     device.buffering.fragment_size = "65536"
   30. I: sink.c:     device.access_mode = "mmap+timer"
   31. I: sink.c:     device.profile.name = "analog-stereo"
   32. I: sink.c:     device.profile.description = "Analog Stereo"
   33. I: sink.c:     device.description = "Internal Audio Analog Stereo"
   34. I: sink.c:     alsa.mixer_name = "Analog Devices AD1981B"
   35. I: sink.c:     alsa.components = "AC97a:41445374"
   36. I: sink.c:     module-udev-detect.discovered = "1"
   37. I: sink.c:     device.icon_name = "audio-card-pci"


intel8x0 does not has hdmi , it seem PA hardcode hdmi for all sound cards
instead of using namehint for playback device

   1. D: alsa-mixer.c: Looking at profile output:hdmi-stereo
   2. D: alsa-mixer.c: Checking for playback on Digital Stereo (HDMI)
   (hdmi-stereo)
   3. D: alsa-util.c: Trying hdmi:0 with SND_PCM_NO_AUTO_FORMAT ...
   4. I: (alsa-lib)conf.c: Unknown parameters 0
   5. I: (alsa-lib)pcm.c: Unknown PCM hdmi:0
   6. I: alsa-util.c: Error opening PCM device hdmi:0: Invalid argument

Is it possible to add timestamp in alsa-sink.c: Wrote 31792 bytes (of
possible 31792 bytes) statement for debugging


   1. D: alsa-sink.c: Loop
   2. D: alsa-sink.c: Buffer time: 371 ms; Sleep time: 351 ms; Process time:
   20 ms
   3. hwptr 7948 buffer 16384 appl 16384, avail=7948
   4. D: alsa-sink.c: avail: 31792 (samples 7948)
   5. D: alsa-sink.c: 191.29 ms left to play; inc threshold = 0.00 ms; dec
   threshold = 100.00 ms
   6. D: alsa-sink.c: Filling up
   7. hwptr 7948 buffer 16384 appl 16384, avail=7948
   8. hwptr 7948 buffer 16384 appl 16384, avail=7948
   9. D: alsa-sink.c: Wrote 31792 bytes (of possible 31792 bytes)
   10. hwptr 7960 buffer 16384 appl 24332, avail=12
   11. D: alsa-sink.c: avail: 48 (samples 12)
   12. D: alsa-sink.c: 371.25 ms left to play; inc threshold = 0.00 ms; dec
   threshold = 100.00 ms
   13. D: alsa-sink.c: Not filling up, because too early.
   14. D: alsa-sink.c: Wakeup from ALSA!
   15. D: alsa-sink.c: Loop
   16. D: alsa-sink.c: Buffer time: 371 ms; Sleep time: 351 ms; Process
   time: 20 ms
   17. hwptr 24351 buffer 16384 appl 24332, avail=16403
   18. E: alsa-util.c: avail 16403 delay -19
   19. D: alsa-sink.c: avail: 65536 (samples 16384)
   20. D: alsa-sink.c: 0.00 ms left to play; inc threshold = 0.00 ms; dec
   threshold = 100.00 ms
   21. D: alsa-sink.c: Filling up