periodic audio skips with Intel HDA

When running PulseAudio, if I'm playing music via any source (Exaile, Totem, Flash in Firefox or Chromium, VLC, etc.) every few minutes the audio will skip once or twice. top doesn't show any process eating CPU any more when it happens. dmesg doesn't show anything. Nothing else seems to be affected. It doesn't seem to happen regularly.

I just installed Ubuntu 12.04 from scratch (with pulseaudio 1:1.1-0ubuntu15), but the same thing happened in 10.04 on the same hardware. Uninstalling the PulseAudio packages and going back to ALSA gives me no issues whatsoever, which is how I know the issue is with PulseAudio. I'm using my onboard audio device:

$ lspci | grep Audio
00:14.2 Audio device: Advanced Micro Devices [AMD] nee ATI SBx00 Azalia (Intel HDA)

Following mailing list instructions, pulseaudio -vvvv --log-time shows during a skip:

( 684.030| 5.000) I: [alsa-sink] alsa-sink.c: Underrun!
( 684.030| 0.000) I: [alsa-sink] alsa-sink.c: Increasing minimal latency to 26.00 ms
( 684.030| 0.000) D: [alsa-sink] alsa-sink.c: Latency set to 26.00ms
( 684.030| 0.000) D: [alsa-sink] alsa-sink.c: hwbuf_unused=60952
( 684.030| 0.000) D: [alsa-sink] alsa-sink.c: setting avail_min=15944
( 684.030| 0.000) D: [alsa-sink] alsa-sink.c: Latency set to 26.00ms
( 684.030| 0.000) D: [alsa-sink] alsa-sink.c: hwbuf_unused=60952
( 684.030| 0.000) D: [alsa-sink] alsa-sink.c: setting avail_min=15944
( 684.031| 0.000) D: [alsa-sink] protocol-native.c: Underrun on 'ALSA Playback', 0 bytes in queue.
( 684.036| 0.004) D: [alsa-sink] protocol-native.c: Requesting rewind due to end of underrun.
( 684.036| 0.000) D: [alsa-sink] alsa-sink.c: Requested to rewind 10940 bytes.
( 684.036| 0.000) D: [alsa-sink] alsa-sink.c: Limited to 3320 bytes.
( 684.036| 0.000) D: [alsa-sink] alsa-sink.c: before: 830
( 684.036| 0.000) D: [alsa-sink] alsa-sink.c: after: 830
( 684.036| 0.000) D: [alsa-sink] alsa-sink.c: Rewound 3320 bytes.
( 684.036| 0.000) D: [alsa-sink] sink.c: Processing rewind...
( 684.036| 0.000) D: [alsa-sink] sink.c: latency = 1337
( 684.036| 0.000) D: [alsa-sink] sink-input.c: Have to rewind 3320 bytes on render memblockq.
( 684.036| 0.000) D: [alsa-sink] source.c: Processing rewind...
( 696.234| 12.197) I: [alsa-sink] alsa-sink.c: Underrun!
( 696.234| 0.000) I: [alsa-sink] alsa-sink.c: Increasing wakeup watermark to 15.99 ms
( 702.033| 5.799) I: [alsa-sink] alsa-sink.c: Underrun!
( 702.033| 0.000) I: [alsa-sink] alsa-sink.c: Increasing minimal latency to 36.00 ms
( 702.033| 0.000) D: [alsa-sink] alsa-sink.c: Latency set to 36.00ms
( 702.033| 0.000) D: [alsa-sink] alsa-sink.c: hwbuf_unused=59188
( 702.033| 0.000) D: [alsa-sink] alsa-sink.c: setting avail_min=15680
( 702.033| 0.000) D: [alsa-sink] alsa-sink.c: Latency set to 36.00ms
( 702.034| 0.000) D: [alsa-sink] alsa-sink.c: hwbuf_unused=59188
( 702.034| 0.000) D: [alsa-sink] alsa-sink.c: setting avail_min=15680
( 702.034| 0.000) D: [alsa-sink] protocol-native.c: Underrun on 'ALSA Playback', 0 bytes in queue.

...and it goes on.

The "Underrun!" messages alone happened a few times before, but it didn't skip.

I'd like to use PulseAudio, but it's pretty annoy...

>
> ( 684.030| 5.000) I: [alsa-sink] alsa-sink.c: Underrun!
> ( 684.030| 0.000) I: [alsa-sink] alsa-sink.c: Increasing minimal latency to
> 26.00 ms
> ( 684.030| 0.000) D: [alsa-sink] alsa-sink.c: Latency set to 26.00ms

The latency is too small, it will make pulseaudio more busy and could not read enough data. So would you have a try to tune the default buffer size and check what will happen?

for me i once met similar case, flood of underrun message caused by too little buffer size, it become better by tune "default-fragment-size-msec" at:
/etc/pulse/daemon.conf

>
> ...and it goes on.
>
> The "Underrun!" messages alone happened a few times before, but it didn't skip.
>
> I'd like to use PulseAudio, but it's pretty annoying having audio skip all the
> time.

Changed default-fragment-size-msec from 10 to 100; still happens.

I tried bumping default-fragment-size-msec up to 1000 and then 10000. It continues to skip.

Regarding "latency", when default-fragment-size-msec was 10000, I noticed a line saying

( 124.922| 0.000) D: [alsa-sink] sink.c: latency = 1339

in the log during a skip. After the music was done skipping, I noticed this:

( 155.288| 0.000) D: [alsa-sink] alsa-sink.c: Latency set to 20.00ms

Not sure which one to believe for "latency".

Anyway, the problem persists regardless of the default-fragment-size-msec config setting.

Created attachment 113034
Underruns in the log

Same with VIA VT1708S. When I start pavucontrol it skips hardly and almost stops sometimes. Because of that latency increases and may get up to 80 ms which is unacceptable as PulseAudio's goal is to provide low latency audio. Of course, it doesn't happen with pure ALSA. I already set all priorities to the maximum, doesn't seem to help. My kernel is preemptive (not the default Debian's one, it's even worse with it):
Linux work 3.18.0-pf0+ #1 SMP PREEMPT Tue Jan 13 09:21:17 MSK 2015 x86_64 GNU/Linux

I have this enabled in daemon.conf:
high-priority = yes
nice-level = -19
realtime-scheduling = yes
realtime-priority = 15
exit-idle-time = -1
log-level = debug

This doesn't happen with tsched=0, but the resulting latency is horrible in that case. Pure ALSA has negligible latency and doesn't skip at all.

Created attachment 113035
alsa-info

08:47:21 work pulseaudio[2333]: Requested tlength=34.83 ms, minreq=5.80 ms
Feb 02 08:47:21 work pulseaudio[2333]: Adjust latency mode enabled, configuring sink latency to half of overall latency.
Feb 02 08:47:21 work pulseaudio[2333]: Requested latency=11.61 ms, Received latency=11.61 ms
Feb 02 08:47:21 work pulseaudio[2333]: memblockq requested: maxlength=4194304, tlength=4096, base=4, prebuf=3076, minreq=1024 maxrewind=0
Feb 02 08:47:21 work pulseaudio[2333]: memblockq sanitized: maxlength=4194304, tlength=4096, base=4, prebuf=3076, minreq=1024 maxrewind=0
Feb 02 08:47:21 work pulseaudio[2333]: Final latency 34.83 ms = 11.61 ms + 2*5.80 ms + 11.61 ms
Feb 02 08:47:21 work pulseaudio[2333]: Latency set to 11.61ms
Feb 02 08:47:21 work pulseaudio[2333]: hwbuf_unused=63488
Feb 02 08:47:21 work pulseaudio[2333]: setting avail_min=16129
Feb 02 08:47:21 work pulseaudio[2333]: Requesting rewind due to latency change.

how did pulseaudio adjust time sched watermark 20ms when client request latency 11.61 ms ?

Created attachment 113083
Underruns with prealloc=2048

I was able to leverage the "Underrun!" issue by setting prealloc to 2048 in kernel options (recompiled it). It can also be achieved via echo 2048 > /proc/asound/card0/pcm0p/sub0/prealloc without recompiling. Wonder why 64 is still default in Debian/Ubuntu. So it doesn't change the latency/watermark now this hard. However, I still get "Underrun!" after launching LMMS. It also spams the syslog with

Feb 03 08:58:35 work pulseaudio[1895]: Pool full

And there are still clicks in the playback from time to time.

(In reply to rkfg from comment #7)
> Created attachment 113083 [details]
> Underruns with prealloc=2048
>
> I was able to leverage the "Underrun!" issue by setting prealloc to 2048 in
> kernel options (recompiled it). It can also be achieved via echo 2048 >
> /proc/asound/card0/pcm0p/sub0/prealloc without recompiling. Wonder why 64 is
> still default in Debian/Ubuntu. So it doesn't change the latency/watermark
> now this hard. However, I still get "Underrun!" after launching LMMS. It
> also spams the syslog with
>
> Feb 03 08:58:35 work pulseaudio[1895]: Pool full
>
> And there are still clicks in the playback from time to time.

do your lmms using 256 frames buffer 5.80 ms ?

try change audio to alsa and change default to hw:0 if you want low latency

LMMS uses 64 frames, 1.5 ms but actually it has latency of 30-35 ms as "pacmd list-sink-inputs" says. Setting its output to ALSA results in extremely garbled sound, the only two options that actually produce reasonable sound is PulseAudio (bad latency) and SDL. Actually, latency isn't that bad if only PA doesn't increase it internally for every client.

I've got a decent CPU here, G620 @ 2.6 GHz so I may understand skipping on high CPU load, BUT PulseAudio has very high realtime priority (15) and if I use pure ALSA there are no skips.

To elaborate: I get garbled sound in LMMS when I use PulseAudio and set LMMS to use ALSA so it's intercepted. Everything is fine if I use pure ALSA everywhere but it's not the point here if we try to debug PA.

(In reply to rkfg from comment #9)
> LMMS uses 64 frames, 1.5 ms but actually it has latency of 30-35 ms as
> "pacmd list-sink-inputs" says. Setting its output to ALSA results in
> extremely garbled sound, the only two options that actually produce
> reasonable sound is PulseAudio (bad latency) and SDL. Actually, latency
> isn't that bad if only PA doesn't increase it internally for every client.
>
> I've got a decent CPU here, G620 @ 2.6 GHz so I may understand skipping on
> high CPU load, BUT PulseAudio has very high realtime priority (15) and if I
> use pure ALSA there are no skips.

Refer to src/core/audio/AudioAlsa.cpp, it using 8 periods per buffer,

 how can lmms use 64 frames ?

minimum period bytes of snd-hda-intel and pulse plugin are 128 bytes (32 frames)

m_periodSize = mixer()->framesPerPeriod();
  m_bufferSize = m_periodSize * 8;

refer to src/core/Audio/AudioPulseAudio.cpp,

               buffer_attr.maxlength = (uint32_t)(-1);

   // play silence in case of buffer underun instead of using default rewind
   buffer_attr.prebuf = 0;

   buffer_attr.minreq = (uint32_t)(-1);
   buffer_attr.fragsize = (uint32_t)(-1);

   double latency = (double)( Engine::mixer()->framesPerPeriod() ) /
              (double)_this->sampleRate();

    // ask PulseAudio for the desired latency (which might not be approved)
    buffer_attr.tlength = pa_usec_to_bytes( latency * PA_USEC_PER_MSEC,
              &_this->m_sampleSpec );

   pa_stream_connect_playback( _this->m_s, NULL, &buffer_attr,
           PA_STREAM_ADJUST_LATENCY,
           NULL, // volume
           NULL );
    break;

I don't know, it's what I set in the LMMS settings: http://i.imgur.com/MRYJC4J.png

Anyway, no matter what I set in one particular program, other clients should not skip because of that.

Created attachment 113112
High latency because of underruns

Nah, after all prealloc is just snake oil. I now have latency of 66 ms which is unacceptable.

1 sink(s) available.
  * index: 0
 name: <alsa_output.pci-0000_00_1b.0.analog-stereo>
 driver: <module-alsa-card.c>
 flags: HARDWARE HW_MUTE_CTRL HW_VOLUME_CTRL DECIBEL_VOLUME LATENCY FLAT_VOLUME DYNAMIC_LATENCY
 state: RUNNING
 suspend cause:
 priority: 9959
 volume: front-left: 65536 / 100% / 0.00 dB, front-right: 65536 / 100% / 0.00 dB
         balance 0.00
 base volume: 65536 / 100% / 0.00 dB
 volume steps: 65537
 muted: no
 current latency: 65.83 ms
 max request: 11 KiB
 max rewind: 344 KiB
 monitor source: 0
 sample spec: s16le 2ch 44100Hz
 channel map: front-left,front-right
              Stereo
 used by: 3
 linked by: 3
 configured latency: 66.00 ms; range is 66.00 .. 2000.00 ms
 card: 0 <alsa_card.pci-0000_00_1b.0>
 module: 6
 properties:
  alsa.resolution_bits = "16"
  device.api = "alsa"
  device.class = "sound"
  alsa.class = "generic"
  alsa.subclass = "generic-mix"
  alsa.name = "VT1708S Analog"
  alsa.id = "VT1708S Analog"
  alsa.subdevice = "0"
  alsa.subdevice_name = "subdevice #0"
  alsa.device = "0"
  alsa.card = "0"
  alsa.card_name = "HDA Intel PCH"
  alsa.long_card_name = "HDA Intel PCH at 0xfe400000 irq 33"
  alsa.driver_name = "snd_hda_intel"
  device.bus_path = "pci-0000:00:1b.0"
  sysfs.path = "/devices/pci0000:00/0000:00:1b.0/sound/card0"
  device.bus = "pci"
  device.vendor.id = "8086"
  device.vendor.name = "Intel Corporation"
  device.product.id = "1c20"
  device.product.name = "6 Series/C200 Series Chipset Family High Definition Audio Controller"
  device.form_factor = "internal"
  device.string = "front:0"
  device.buffering.buffer_size = "352800"
  device.buffering.fragment_size = "176400"
  device.access_mode = "mmap+timer"
  device.profile.name = "analog-stereo"
  device.profile.description = "Analog Stereo"
  device.description = "Built-in Audio Analog Stereo"
  alsa.mixer_name = "VIA VT1708S"
  alsa.components = "HDA:11060397,10438415,00100000"
  module-udev-detect.discovered = "1"
  device.icon_name = "audio-card-pci"
 ports:
  analog-output: Analog Output (priority 9900, latency offset 0 usec, available: unknown)
   properties:

  analog-output-lineout: Line Out (priority 9900, latency offset 0 usec, available: yes)
   properties:

  analog-output-headphones: Headphones (priority 9000, latency offset 0 usec, available: no)
   properties:
    device.icon_name = "audio-headphones"
 active port: <analog-output>

Any suggestions outside of forcing a fixed latency?

which motherboard are you using ?

do this motherboard support internal spdif connector to graphic card ?

it is rare that it only has internal spdif connector but not optical/rca digital output

You can also connect the onboard header to an S/PDIF input header available on some graphics cards using an S/PDIF cable. This connection routes digital audio to the HDMI output of the graphics card.

http://www.intel.com/support/motherboards/desktop/sb/CS-032871.htm

Node 0x20 [Pin Complex] wcaps 0x400701: Stereo Digital
  Control: name="HDMI Phantom Jack", index=0, device=0
  Pincap 0x00000010: OUT
  Pin Default 0x185600f0: [Jack] Digital Out at Int HDMI
    Conn = Digital, Color = Unknown
    DefAssociation = 0xf, Sequence = 0x0
  Pin-ctls: 0x40: OUT
  Power states: D0 D1 D2 D3
  Power: setting=D0, actual=D0
  Connection: 1
     0x12

APLAY

**** List of PLAYBACK Hardware Devices ****
card 0: PCH [HDA Intel PCH], device 0: VT1708S Analog [VT1708S Analog]
  Subdevices: 0/1
  Subdevice #0: subdevice #0
card 0: PCH [HDA Intel PCH], device 2: VT1708S Alt Analog [VT1708S Alt Analog]
  Subdevices: 1/1
  Subdevice #0: subdevice #0
card 0: PCH [HDA Intel PCH], device 3: VT1708S Digital [VT1708S Digital]
  Subdevices: 1/1
  Subdevice #0: subdevice #0

Base Board Information
        Manufacturer: ASUSTeK Computer INC.
        Product Name: P8H61-M LX2

> You can also connect the onboard header to an S/PDIF input header available on some graphics cards using an S/PDIF cable.

I don't have any digital audio equipment, only headphones with a regular jack.

how low latecy can you get with paplay

paplay -l-latency-msec=5 -v any.wav

what is the smallest buffer size using aplay without underrun (eg. 1024, 512, 256, 128, 64)

aplay -D hw:0,0 -v --buffer-size=1024 any.wav

It turned out that garbled sound in LMMS with alsa output was because of "options snd-hda-intel position_fix=1" I used in module options. Tried to fix this skips but it didn't work. After removing this option and reloading the snd_hda_intel module, LMMS sounds much better with alsa output but that clicks are still audible sometimes. PA also seems to lower latency after an underrun occures as I see in the log latency increasing like 1-2-4-8-4-8.

The lowest latency I've got with paplay is 8 msec, any less produces clicks or garbled sound.

> aplay -D hw:0,0 -v --buffer-size=1024 /usr/share/sounds/alsa/Front_Center.wav
Playing WAVE '/usr/share/sounds/alsa/Front_Center.wav' : Signed 16 bit Little Endian, Rate 48000 Hz, Mono
aplay: set_params:1239: Channels count non available

However, device "default" works fine. The lowest buffer size that doesn't underrun is 3072.

I was too fast coming to conclusions. ALSA plugin in LMMS still croaks after PA worked several hours and gained latency of 36.00ms currently. It may go down if I disconnect all its clients but I'm listening to music all the day while working so it's not an option. Underruns happen more often if LMMS is just working in the background not doing anything.

>
> > aplay -D hw:0,0 -v --buffer-size=1024 /usr/share/sounds/alsa/Front_Center.wav
> Playing WAVE '/usr/share/sounds/alsa/Front_Center.wav' : Signed 16 bit
> Little Endian, Rate 48000 Hz, Mono
> aplay: set_params:1239: Channels count non available
>
> However, device "default" works fine. The lowest buffer size that doesn't
> underrun is 3072.

you need to use a stereo wav file since snd-hda-intel support stereo only

https://git.kernel.org/cgit/linux/kernel/git/tiwai/sound.git/commit/sound/pci/hda/hda_intel.c?id=2ae66c26550cd94b0e2606a9275eb0ab7070ad0e

seem some hda controller support arbitary period size , i.e. periods size can be not multiple of 32 frames

Ok, so 1024 overruns:
# aplay -D hw:0,0 -v --buffer-size=1024 /tmp/fr025.wav
Playing WAVE '/tmp/fr025.wav' : Signed 16 bit Little Endian, Rate 44100 Hz, Stereo
Hardware PCM card 0 'HDA Intel PCH' device 0 subdevice 0
Its setup is:
  stream : PLAYBACK
  access : RW_INTERLEAVED
  format : S16_LE
  subformat : STD
  channels : 2
  rate : 44100
  exact rate : 44100 (44100/1)
  msbits : 16
  buffer_size : 1024
  period_size : 256
  period_time : 5804
  tstamp_mode : NONE
  period_step : 1
  avail_min : 256
  period_event : 0
  start_threshold : 1024
  stop_threshold : 1024
  silence_threshold: 0
  silence_size : 0
  boundary : 4611686018427387904
  appl_ptr : 0
  hw_ptr : 0
underrun!!! (at least 2.306 ms long)
Status:
  state : XRUN
  trigger_time: 7298.28726754
  tstamp : 7298.31029657
  delay : 0
  avail : 1177
  avail_max : 1177

2048 does not:

# aplay -D hw:0,0 -v --buffer-size=2048 /tmp/fr025.wav
Playing WAVE '/tmp/fr025.wav' : Signed 16 bit Little Endian, Rate 44100 Hz, Stereo
Hardware PCM card 0 'HDA Intel PCH' device 0 subdevice 0
Its setup is:
  stream : PLAYBACK
  access : RW_INTERLEAVED
  format : S16_LE
  subformat : STD
  channels : 2
  rate : 44100
  exact rate : 44100 (44100/1)
  msbits : 16
  buffer_size : 2048
  period_size : 512
  period_time : 11609
  tstamp_mode : NONE
  period_step : 1
  avail_min : 512
  period_event : 0
  start_threshold : 2048
  stop_threshold : 2048
  silence_threshold: 0
  silence_size : 0
  boundary : 4611686018427387904
  appl_ptr : 0
  hw_ptr : 0

Feb 03 08:48:16 work pulseaudio[1895]: Maximum hw buffer size is 11888 ms
Feb 03 08:48:16 work pulseaudio[1895]: Set buffer size first (to 4408 samples), period size second (to 1102 samples).
Feb 03 08:48:16 work pulseaud

seem support arbitrary buffer/period sizes since 1102 is not multiple of 32 bytes

can aplay use buffer size 1500 or 2000 ?

# aplay -D hw:0,0 -v --buffer-size=1500 /tmp/fr025.wav
Playing WAVE '/tmp/fr025.wav' : Signed 16 bit Little Endian, Rate 44100 Hz, Stereo
Hardware PCM card 0 'HDA Intel PCH' device 0 subdevice 0
Its setup is:
  stream : PLAYBACK
  access : RW_INTERLEAVED
  format : S16_LE
  subformat : STD
  channels : 2
  rate : 44100
  exact rate : 44100 (44100/1)
  msbits : 16
  buffer_size : 1500
  period_size : 375
  period_time : 8503
  tstamp_mode : NONE
  period_step : 1
  avail_min : 375
  period_event : 0
  start_threshold : 1500
  stop_threshold : 1500
  silence_threshold: 0
  silence_size : 0
  boundary : 6755399441055744000
  appl_ptr : 0
  hw_ptr : 0

# aplay -D hw:0,0 -v --buffer-size=2000 /tmp/fr025.wav
Playing WAVE '/tmp/fr025.wav' : Signed 16 bit Little Endian, Rate 44100 Hz, Stereo
Hardware PCM card 0 'HDA Intel PCH' device 0 subdevice 0
Its setup is:
  stream : PLAYBACK
  access : RW_INTERLEAVED
  format : S16_LE
  subformat : STD
  channels : 2
  rate : 44100
  exact rate : 44100 (44100/1)
  msbits : 16
  buffer_size : 2000
  period_size : 500
  period_time : 11337
  tstamp_mode : NONE
  period_step : 1
  avail_min : 500
  period_event : 0
  start_threshold : 2000
  stop_threshold : 2000
  silence_threshold: 0
  silence_size : 0
  boundary : 9007199254740992000
  appl_ptr : 0
  hw_ptr : 0

Any ideas? The issue doesn't seem to resolve itself.

So I've bought a laptop with VIA sound as well and it also have skips/stutters. I worked around it on both systems with these steps:

1) in /etc/pulse/default.pa added tsched=0:
load-module module-udev-detect tsched=0

2) to reduce latency set in /etc/pulse/daemon.conf:
default-fragments = 4
default-fragment-size-msec = 1

The final latency is a product of these numbers, 1*4 == 4 ms which is acceptable. The number of fragments should be at least 2 so the least latency possible is 2*1 == 2 ms. I don't know if there's a real difference between 4 fragments of 1 ms each or 2 fragments of 2 ms each. Try some experimenting. At least now I don't have latency increase and sound doesn't skip on pavucontrol launch, though it still skips on LMMS launch.

Based on the comments' content and timestamps here, it looks to me that no one in PA team really cares about HDA Intel cards which are the most popular cards. And if PA performs badly with them out of the box it hurts PA's face, no matter who's to blame actually. Plus, pure ALSA works fine or doesn't work at all, usually.

(In reply to rkfg from comment #26)
> So I've bought a laptop with VIA sound as well and it also have
> skips/stutters. I worked around it on both systems with these steps:
>
> 1) in /etc/pulse/default.pa added tsched=0:
> load-module module-udev-detect tsched=0
>
> 2) to reduce latency set in /etc/pulse/daemon.conf:
> default-fragments = 4
> default-fragment-size-msec = 1
>
> The final latency is a product of these numbers, 1*4 == 4 ms which is
> acceptable. The number of fragments should be at least 2 so the least
> latency possible is 2*1 == 2 ms. I don't know if there's a real difference
> between 4 fragments of 1 ms each or 2 fragments of 2 ms each. Try some
> experimenting. At least now I don't have latency increase and sound doesn't
> skip on pavucontrol launch, though it still skips on LMMS launch.
>

are there any difference when using four periods or two periods ?

 1ms at 44100 Hz has 44.1 frames

aplay select buffer size nearest to the selected time

aplay -D hw:0,0 -v --buffer-time=4000 /tmp/fr025.wav

aplay -D hw:0,0 -v --period-time=2000 --buffer-time=4000 /tmp/fr025.wav

Both commands produce underruns at large, audible and visible in the output.

> aplay -D hw:0,0 -v --buffer-time=4000 /tmp/fr025.wav
Playing WAVE '/tmp/fr025.wav' : Signed 16 bit Little Endian, Rate 44100 Hz, Stereo
Hardware PCM card 0 'HDA Intel PCH' device 0 subdevice 0
Its setup is:
  stream : PLAYBACK
  access : RW_INTERLEAVED
  format : S16_LE
  subformat : STD
  channels : 2
  rate : 44100
  exact rate : 44100 (44100/1)
  msbits : 16
  buffer_size : 192
  period_size : 32
  period_time : 725
  tstamp_mode : NONE
  period_step : 1
  avail_min : 32
  period_event : 0
  start_threshold : 192
  stop_threshold : 192
  silence_threshold: 0
  silence_size : 0
  boundary : 6917529027641081856
  appl_ptr : 0
  hw_ptr : 0
underrun!!! (at least 4.191 ms long)
Status:
  state : XRUN
  trigger_time: 3336.7694317
  tstamp : 3336.11882117
  delay : 0
  avail : 200
  avail_max : 200
underrun!!! (at least 1.832 ms long)
Status:
  state : XRUN
  trigger_time: 3336.30152303
  tstamp : 3336.31983077
  delay : 0
  avail : 194
  avail_max : 194
underrun!!! (at least 0.312 ms long)
Status:
  state : XRUN
  trigger_time: 3337.6068547
  tstamp : 3337.6379149
  delay : 0
  avail : 200
  avail_max : 200
underrun!!! (at least 4.293 ms long)
Status:
  state : XRUN
  trigger_time: 3339.4484089
  tstamp : 3339.8775797
  delay : 0
  avail : 200
  avail_max : 200
underrun!!! (at least 11.592 ms long)
Status:
  state : XRUN
  trigger_time: 3343.6272217
  tstamp : 3343.17862683
  delay : 0
  avail : 200
  avail_max : 200
underrun!!! (at least 2.310 ms long)
Status:
  state : XRUN
  trigger_time: 3343.700965780
  tstamp : 3343.703274524
  delay : 0
  avail : 200
  avail_max : 200
^CAborted by signal Interrupt...

> aplay -D hw:0,0 -v --period-time=2000 --buffer-time=4000 /tmp/fr025.wav
Playing WAVE '/tmp/fr025.wav' : Signed 16 bit Little Endian, Rate 44100 Hz, Stereo
Hardware PCM card 0 'HDA Intel PCH' device 0 subdevice 0
Its setup is:
  stream : PLAYBACK
  access : RW_INTERLEAVED
  format : S16_LE
  subformat : STD
  channels : 2
  rate : 44100
  exact rate : 44100 (44100/1)
  msbits : 16
  buffer_size : 192
  period_size : 96
  period_time : 2176
  tstamp_mode : NONE
  period_step : 1
  avail_min : 96
  period_event : 0
  start_threshold : 192
  stop_threshold : 192
  silence_threshold: 0
  silence_size : 0
  boundary : 6917529027641081856
  appl_ptr : 0
  hw_ptr : 0
underrun!!! (at least 8.673 ms long)
Status:
  state : XRUN
  trigger_time: 3355.4367755
  tstamp : 3355.13037189
  delay : 0
  avail : 200
  avail_max : 200
underrun!!! (at least 2.189 ms long)
Status:
  state : XRUN
  trigger_time: 3356.24657841
  tstamp : 3356.26845873
  delay : 0
  avail : 200
  avail_max : 200
underrun!!! (at least 2.160 ms long)
Status:
  state : XRUN
  trigger_time: 3358.690871062
  tstamp : 3358.693029225
  delay : 0
  avail : 281
 ...

I've found that 16000 buffer time with 4000 period time doesn't underrun while if I change the period time to 1000 or 2000 it underruns pretty quickly. Lower buffer times underrun regardless of the period time it seems.

16000/4000 shows these params:

> aplay -D hw:0,0 -v --buffer-time=16000 --period-time=4000 /tmp/fr025.wav
Playing WAVE '/tmp/fr025.wav' : Signed 16 bit Little Endian, Rate 44100 Hz, Stereo
Hardware PCM card 0 'HDA Intel PCH' device 0 subdevice 0
Its setup is:
  stream : PLAYBACK
  access : RW_INTERLEAVED
  format : S16_LE
  subformat : STD
  channels : 2
  rate : 44100
  exact rate : 44100 (44100/1)
  msbits : 16
  buffer_size : 768
  period_size : 192
  period_time : 4353
  tstamp_mode : NONE
  period_step : 1
  avail_min : 192
  period_event : 0
  start_threshold : 768
  stop_threshold : 768
  silence_threshold: 0
  silence_size : 0
  boundary : 6917529027641081856
  appl_ptr : 0
  hw_ptr : 0

16000/2000 is like this:

> aplay -D hw:0,0 -v --buffer-time=16000 --period-time=2000 /tmp/fr025.wav
Playing WAVE '/tmp/fr025.wav' : Signed 16 bit Little Endian, Rate 44100 Hz, Stereo
Hardware PCM card 0 'HDA Intel PCH' device 0 subdevice 0
Its setup is:
  stream : PLAYBACK
  access : RW_INTERLEAVED
  format : S16_LE
  subformat : STD
  channels : 2
  rate : 44100
  exact rate : 44100 (44100/1)
  msbits : 16
  buffer_size : 672
  period_size : 96
  period_time : 2176
  tstamp_mode : NONE
  period_step : 1
  avail_min : 96
  period_event : 0
  start_threshold : 672
  stop_threshold : 672
  silence_threshold: 0
  silence_size : 0
  boundary : 6052837899185946624
  appl_ptr : 0
  hw_ptr : 0
underrun!!! (at least 2.587 ms long)
Status:
  state : XRUN
  trigger_time: 4380.16449247
  tstamp : 4380.19033473
  delay : 0
  avail : 761
  avail_max : 761
^CAborted by signal Interrupt...

Also, when CPU is loaded for any reason I sometimes get this:

Apr 09 11:56:10 work pulseaudio[9718]: [alsa-sink-VT1708S Analog] protocol-native.c: Implicit underrun of 'Playback'
Apr 09 11:56:10 work pulseaudio[9718]: [alsa-sink-VT1708S Analog] sink.c: Found underrun 1380 bytes ago (1436 bytes ahead in playback buffer)
Apr 09 11:56:10 work pulseaudio[9718]: [alsa-sink-VT1708S Analog] protocol-native.c: Requesting rewind due to end of underrun.
Apr 09 11:56:10 work pulseaudio[9718]: [alsa-sink-VT1708S Analog] alsa-sink.c: Requested to rewind 2816 bytes.
Apr 09 11:56:10 work pulseaudio[9718]: [alsa-sink-VT1708S Analog] alsa-sink.c: Limited to 2560 bytes.
Apr 09 11:56:10 work pulseaudio[9718]: [alsa-sink-VT1708S Analog] alsa-sink.c: before: 640
Apr 09 11:56:10 work pulseaudio[9718]: [alsa-sink-VT1708S Analog] alsa-sink.c: after: 640
Apr 09 11:56:10 work pulseaudio[9718]: [alsa-sink-VT1708S Analog] alsa-sink.c: Rewound 2560 bytes.
Apr 09 11:56:10 work pulseaudio[9718]: [alsa-sink-VT1708S Analog] sink.c: Processing rewind...
Apr 09 11:56:10 work pulseaudio[9718]: [alsa-sink-VT1708S Analog] sink.c: latency = 1302
Apr 09 11:56:10 work pulseaudio[9718]: [alsa-sink-VT1708S Analog] sink-input.c: Have to rewind 2560 bytes on render memblockq.
Apr 09 11:56:10 work pulseaudio[9718]: [alsa-sink-VT1708S Analog] source.c: Processing rewind...
Apr 09 11:56:10 work pulseaudio[9718]: [alsa-sink-VT1708S Analog] alsa-util.c: snd_pcm_avail() returned a value that is exceptionally large: 32960 bytes (186 ms).
Apr 09 11:56:10 work pulseaudio[9718]: [alsa-sink-VT1708S Analog] alsa-util.c: Most likely this is a bug in the ALSA driver 'snd_hda_intel'. Please report this issue to the ALSA developers.
Apr 09 11:56:10 work pulseaudio[9718]: [alsa-sink-VT1708S Analog] alsa-util.c: snd_pcm_dump():
Apr 09 11:56:10 work pulseaudio[9718]: [alsa-sink-VT1708S Analog] alsa-util.c: Soft volume PCM
Apr 09 11:56:10 work pulseaudio[9718]: [alsa-sink-VT1708S Analog] alsa-util.c: Control: PCM Playback Volume
Apr 09 11:56:10 work pulseaudio[9718]: [alsa-sink-VT1708S Analog] alsa-util.c: min_dB: -51
Apr 09 11:56:10 work pulseaudio[9718]: [alsa-sink-VT1708S Analog] alsa-util.c: max_dB: 0
Apr 09 11:56:10 work pulseaudio[9718]: [alsa-sink-VT1708S Analog] alsa-util.c: resolution: 256
Apr 09 11:56:10 work pulseaudio[9718]: [alsa-sink-VT1708S Analog] alsa-util.c: Its setup is:
Apr 09 11:56:10 work pulseaudio[9718]: [alsa-sink-VT1708S Analog] alsa-util.c: stream : PLAYBACK
Apr 09 11:56:10 work pulseaudio[9718]: [alsa-sink-VT1708S Analog] alsa-util.c: access : MMAP_INTERLEAVED
Apr 09 11:56:10 work pulseaudio[9718]: [alsa-sink-VT1708S Analog] alsa-util.c: format : S16_LE
Apr 09 11:56:10 work pulseaudio[9718]: [alsa-sink-VT1708S Analog] alsa-util.c: subformat : STD
Apr 09 11:56:10 work pulseaudio[9718]: [alsa-sink-VT1708S Analog] alsa-util.c: channels : 2
Apr 09 11:56:10 work pulseaudio[9718]: [alsa-sink-VT1708S Analog] alsa-util.c: rate : 44100
Apr 09 11:56:10 work pulseaudio[9718]: [alsa-sink-VT1708S Analog] alsa-util.c: exact rate : 44100 (44100/1)
Apr 09 11:56:10 work pulseaudio[9718]: [alsa-sink-VT1708S Analog] alsa-util.c: msbits : 16...

(I
>
> Also, after I do:
> echo 1 > /proc/asound/card0/pcm0p/xrun_debug
>
> I have lots of this in dmesg:
> [ 3504.140844] ALSA: PCM: [Q] Lost interrupts?: (stream=0, delta=56,
> new_hw_ptr=809, old_hw_ptr=753)
> [ 3504.143264] ALSA: PCM: [Q] Lost interrupts?: (stream=0, delta=72,
> new_hw_ptr=913, old_hw_ptr=841)
> [ 3504.148353] ALSA: PCM: [Q] Lost interrupts?: (stream=0, delta=72,
> new_hw_ptr=1137, old_hw_ptr=1065)
> [ 3504.150102] ALSA: PCM: [Q] Lost interrupts?: (stream=0, delta=80,
> new_hw_ptr=1217, old_hw_ptr=1137)
> [ 3504.156337] ALSA: PCM: [Q] Lost interrupts?: (stream=0, delta=72,
> new_hw_ptr=1489, old_hw_ptr=1417)
> [ 3504.157990] ALSA: PCM: [Q] Lost interrupts?: (stream=0, delta=72,
> new_hw_ptr=1561, old_hw_ptr=1489)
> [ 3504.169408] ALSA: PCM: [Q] Lost interrupts?: (stream=0, delta=72,
> new_hw_ptr=2065, old_hw_ptr=1993)
> [ 3504.170967] ALSA: PCM: [Q] Lost interrupts?: (stream=0, delta=72,
> new_hw_ptr=2137, old_hw_ptr=2065)
> [ 3504.179684] ALSA: PCM: [Q] Lost interrupts?: (stream=0, delta=72,
> new_hw_ptr=2521, old_hw_ptr=2449)
> [ 3504.194902] ALSA: PCM: [Q] Lost interrupts?: (stream=0, delta=80,
> new_hw_ptr=121, old_hw_ptr=41)

http://www.alsa-project.org/main/index.php/XRUN_Debug

you need more debug info to find out what happen

Enable basic debugging and dump stack, check hardware pointer on the period update

https://git.kernel.org/cgit/linux/kernel/git/tiwai/sound.git/tree/Documentation/sound/alsa/HD-Audio.txt

how about enable_msi=0 ?

if it don't help, you need to file bug report at

https://bugzilla.kernel.org/enter_bug.cgi?product=Drivers

Created attachment 115003
Syslog with debug info

Here's my full syslog. First I started PA with:
default-fragments = 9
default-fragment-size-msec = 2

So the buffer was 800 frames, I couldn't get it to be 768 to have exactly 16 ms latency. So it was 18 ms. I had no errors in dmesg while using value of 11 for xrun_debug. Then I set params to 4 fragments of 1 ms each and had errors.

enable_msi=0 didn't help IIRC, neither did position_fix. But I'll try again.

enable_msi=0 doesn't change anything, still the same errors in the log.

I don't know if it's related but there's no error messages in dmesg if I run PA without tsched=0. Though in this case skips are pretty audible and the fragment size and their number aren't respected. Even worse, latency grows over time with each skip and becomes unbearable. With tsched=0 I can at least get it fixed. I also have skips when PC is under load (Java compiling, tabs reloading at the same time etc.). PA says it's working in realtime mode so these userland processes should not interfere. It reports in its log that it's the ALSA underrun, not the application's one. So I don't know who's to blame.

When I start PA without tsched=0, it's ALSA setup is weird:

Apr 10 09:46:52 work pulseaudio[5161]: [pulseaudio] alsa-util.c: Control: PCM Playback Volume
Apr 10 09:46:52 work pulseaudio[5161]: [pulseaudio] alsa-util.c: min_dB: -51
Apr 10 09:46:52 work pulseaudio[5161]: [pulseaudio] alsa-util.c: max_dB: 0
Apr 10 09:46:52 work pulseaudio[5161]: [pulseaudio] alsa-util.c: resolution: 256
Apr 10 09:46:52 work pulseaudio[5161]: [pulseaudio] alsa-util.c: Its setup is:
Apr 10 09:46:52 work pulseaudio[5161]: [pulseaudio] alsa-util.c: stream : PLAYBACK
Apr 10 09:46:52 work pulseaudio[5161]: [pulseaudio] alsa-util.c: access : MMAP_INTERLEAVED
Apr 10 09:46:52 work pulseaudio[5161]: [pulseaudio] alsa-util.c: format : S16_LE
Apr 10 09:46:52 work pulseaudio[5161]: [pulseaudio] alsa-util.c: subformat : STD
Apr 10 09:46:52 work pulseaudio[5161]: [pulseaudio] alsa-util.c: channels : 2
Apr 10 09:46:52 work pulseaudio[5161]: [pulseaudio] alsa-util.c: rate : 44100
Apr 10 09:46:52 work pulseaudio[5161]: [pulseaudio] alsa-util.c: exact rate : 44100 (44100/1)
Apr 10 09:46:52 work pulseaudio[5161]: [pulseaudio] alsa-util.c: msbits : 16
Apr 10 09:46:52 work pulseaudio[5161]: [pulseaudio] alsa-util.c: buffer_size : 88192
Apr 10 09:46:52 work pulseaudio[5161]: [pulseaudio] alsa-util.c: period_size : 44096
Apr 10 09:46:52 work pulseaudio[5161]: [pulseaudio] alsa-util.c: period_time : 999909
Apr 10 09:46:52 work pulseaudio[5161]: [pulseaudio] alsa-util.c: tstamp_mode : ENABLE
Apr 10 09:46:52 work pulseaudio[5161]: [pulseaudio] alsa-util.c: period_step : 1
Apr 10 09:46:52 work pulseaudio[5161]: [pulseaudio] alsa-util.c: avail_min : 87310
Apr 10 09:46:52 work pulseaudio[5161]: [pulseaudio] alsa-util.c: period_event : 0
Apr 10 09:46:52 work pulseaudio[5161]: [pulseaudio] alsa-util.c: start_threshold : -1
Apr 10 09:46:52 work pulseaudio[5161]: [pulseaudio] alsa-util.c: stop_threshold : 6205960286516543488
Apr 10 09:46:52 work pulseaudio[5161]: [pulseaudio] alsa-util.c: silence_threshold: 0
Apr 10 09:46:52 work pulseaudio[5161]: [pulseaudio] alsa-util.c: silence_size : 0
Apr 10 09:46:52 work pulseaudio[5161]: [pulseaudio] alsa-util.c: boundary : 6205960286516543488
Apr 10 09:46:52 work pulseaudio[5161]: [pulseaudio] alsa-util.c: Slave: Hardware PCM card 0 'HDA Intel PCH' device 0 subdevice 0
Apr 10 09:46:52 work pulseaudio[5161]: [pulseaudio] alsa-util.c: Its setup is:
Apr 10 09:46:52 work pulseaudio[5161]: [pulseaudio] alsa-util.c: stream : PLAYBACK
Apr 10 09:46:52 work pulseaudio[5161]: [pulseaudio] alsa-util.c: access : MMAP_INTERLEAVED
Apr 10 09:46:52 work pulseaudio[5161]: [pulseaudio] alsa-util.c: format : S16_LE
Apr 10 09:46:52 work pulseaudio[5161]: [pulseaudio] alsa-util.c: subformat : STD
Apr 10 09:46:52 work pulseaudio[5161]: [pulseaudio] alsa-util.c: channels : 2
Apr 10 09:46:52 work pulseaudio[5161]: [pulseaudio] alsa-util.c: rate : 44100
Apr 10 09:46:52 work pulseaudio[5161]: [pulseaudio] alsa-util.c: exact rate : 44100 (44100/1)
Apr 10 09:46:52 work pulseaudio[5161]: [pulseaudio] alsa-util.c: msbits : 16
Apr 10...

(In reply to rkfg from comment #35)
> When I start PA without tsched=0, it's ALSA setup is weird:
>

> Apr 10 09:46:52 work pulseaudio[5161]: [pulseaudio] alsa-util.c: rate
> : 44100
> Apr 10 09:46:52 work pulseaudio[5161]: [pulseaudio] alsa-util.c: exact
> rate : 44100 (44100/1)
> Apr 10 09:46:52 work pulseaudio[5161]: [pulseaudio] alsa-util.c: msbits
> : 16
> Apr 10 09:46:52 work pulseaudio[5161]: [pulseaudio] alsa-util.c:
> buffer_size : 88192
> Apr 10 09:46:52 work pulseaudio[5161]: [pulseaudio] alsa-util.c:
> period_size : 44096
> Apr 10 09:46:52 work pulseaudio[5161]: [pulseaudio] alsa-util.c:
> period_time : 999909
> Apr 10 09:46:52 work pulseaudio[5161]: [pulseaudio] alsa-util.c:
>
>
> Why does period size lack 4 bytes to be exactly 1 second long?

https://git.kernel.org/cgit/linux/kernel/git/tiwai/sound.git/commit/sound/pci/hda/hda_intel.c?id=5f1545bc45a33361d6bb2fb44af7c35bcd733b9d

snd_pcm_hw_constraint_step(runtime, 0, SNDRV_PCM_HW_PARAM_BUFFER_BYTES,
+ 128);
+ snd_pcm_hw_constraint_step(runtime, 0, SNDRV_PCM_HW_PARAM_PERIOD_BYTES,
+ 128);

https://git.kernel.org/cgit/linux/kernel/git/tiwai/sound.git/commit/sound/pci/hda/hda_intel.c?id=103884a351a221553095c509a1dbbbf7d4fd9b05

[ 3504.156337] ALSA: PCM: [Q] Lost interrupts?: (stream=0, delta=72, new_hw_ptr=1489, old_hw_ptr=1417)

do you still get those " ALSA: PCM: [Q] Lost interrupts?: " when you specify align_buffer_size=1 ?

MODULE_PARM_DESC(align_buffer_size,
   "Force buffer and period sizes to be multiple of 128 bytes.");

https://git.kernel.org/cgit/linux/kernel/git/tiwai/sound.git/commit/sound/pci/hda?id=7bfe059e38b06a0d813d92b9b3e500455f6a2c99

I have them with 4 fragments of 1 ms each. tsched=0, device.buffering.buffer_size = "768", device.buffering.fragment_size = "128":

[11966.628405] ALSA: PCM: [Q] Lost interrupts?: (stream=0, delta=72, new_hw_ptr=1177, old_hw_ptr=1105)
[11966.636364] ALSA: PCM: [Q] Lost interrupts?: (stream=0, delta=72, new_hw_ptr=1521, old_hw_ptr=1449)
[11966.668090] ALSA: PCM: [Q] Lost interrupts?: (stream=0, delta=72, new_hw_ptr=505, old_hw_ptr=433)
[11966.671573] ALSA: PCM: [Q] Lost interrupts?: (stream=0, delta=79, new_hw_ptr=672, old_hw_ptr=593)
[11966.676095] ALSA: PCM: [Q] Lost interrupts?: (stream=0, delta=72, new_hw_ptr=889, old_hw_ptr=817)
[11966.681435] ALSA: PCM: [Q] Lost interrupts?: (stream=0, delta=56, new_hw_ptr=1145, old_hw_ptr=1089)
[11966.686940] ALSA: PCM: [Q] Lost interrupts?: (stream=0, delta=80, new_hw_ptr=1409, old_hw_ptr=1329)
[11966.689460] ALSA: PCM: [Q] Lost interrupts?: (stream=0, delta=80, new_hw_ptr=1529, old_hw_ptr=1449)
[11966.692775] ALSA: PCM: [Q] Lost interrupts?: (stream=0, delta=80, new_hw_ptr=1689, old_hw_ptr=1609)
[11966.696944] ALSA: PCM: [Q] Lost interrupts?: (stream=0, delta=80, new_hw_ptr=1889, old_hw_ptr=1809)

# cat /sys/module/snd_hda_intel/parameters/align_buffer_size
1

It has also printed this in the PA's log: http://pastebin.com/jAQx6DEZ

> ALSA woke us up to write new data to the device, but there was actually nothing to write! Most likely this is a bug in the ALSA driver 'snd_hda_intel'. Please report this issue to the ALSA developers. We were woken up with POLLOUT set -- however a subsequent snd_pcm_avail() returned 0 or another value < min_avail.

ALSA setup:

Apr 14 13:51:06 work pulseaudio[11059]: [pulseaudio] alsa-util.c: Control: PCM Playback Volume
Apr 14 13:51:06 work pulseaudio[11059]: [pulseaudio] alsa-util.c: min_dB: -51
Apr 14 13:51:06 work pulseaudio[11059]: [pulseaudio] alsa-util.c: max_dB: 0
Apr 14 13:51:06 work pulseaudio[11059]: [pulseaudio] alsa-util.c: resolution: 256
Apr 14 13:51:06 work pulseaudio[11059]: [pulseaudio] alsa-util.c: Its setup is:
Apr 14 13:51:06 work pulseaudio[11059]: [pulseaudio] alsa-util.c: stream : PLAYBACK
Apr 14 13:51:06 work pulseaudio[11059]: [pulseaudio] alsa-util.c: access : MMAP_INTERLEAVED
Apr 14 13:51:06 work pulseaudio[11059]: [pulseaudio] alsa-util.c: format : S16_LE
Apr 14 13:51:06 work pulseaudio[11059]: [pulseaudio] alsa-util.c: subformat : STD
Apr 14 13:51:06 work pulseaudio[11059]: [pulseaudio] alsa-util.c: channels : 2
Apr 14 13:51:06 work pulseaudio[11059]: [pulseaudio] alsa-util.c: rate : 44100
Apr 14 13:51:06 work pulseaudio[11059]: [pulseaudio] alsa-util.c: exact rate : 44100 (44100/1)
Apr 14 13:51:06 work pulseaudio[11059]: [pulseaudio] alsa-util.c: msbits : 16
Apr 14 13:51:06 work pulseaudio[11059]: [pulseaudio] alsa-util.c: buffer_size : 192
Apr 14 13:51:06 work pulseaudio[11059]: [pulseaudio] alsa-util.c: period_size : 32
Apr 14 13:51:06 work pulseaudio[11059]: [pulseaudio] alsa-util.c: period_time : 725
Apr 14 13:51:06 work pulseaudio[11059]: [pulseaudio] alsa-util.c: tstamp_mode : ENABLE
Apr 14 13:51:06 work pulseaudio[11059]: [pulseaudio] alsa-util.c: period_step : 1
Apr 14 13:51:06 work pulseaudio[11059]: [pulseaudio] alsa-util.c: avail_min : 32
Apr 14 13:51:06 work pulseaudio[11059]: [pulseaudio] alsa-util.c: period_event : 1
Apr 14 13:51:06 work pulseaudio[11059]: [pulseaudio] alsa-util.c: start_threshold : -1
Apr 14 13:51:06 work pulseaudio[11059]: [pulseaudio] alsa-util.c: stop_threshold : 6917529027641081856
Apr 14 13:51:06 work pulseaudio[11059]: [pulseaudio] alsa-util.c: silence_threshold: 0
Apr 14 13:51:06 work pulseaudio[11059]: [pulseaudio] alsa-util.c: silence_size : 0
Apr 14 13:51:06 work pulseaudio[11059]: [pulseaudio] alsa-util.c: boundary : 6917529027641081856
Apr 14 13:51:06 work pulseaudio[11059]: [pulseaudio] alsa-util.c: Slave: Hardware PCM card 0 'HDA Intel PCH' device 0 subdevice 0
Apr 14 13:51:06 work pulseaudio[11059]: [pulseaudio] alsa-util.c: Its setup is:
Apr 14 13:51:06 work pulseaudio[11059]: [pulseaudio] alsa-util.c: stream : PLAYBACK
Apr 14 13:51:06 work pulseaudio[11059]: [pulseaudio] alsa-util.c: access : MMAP_INTERLEAVED
Apr 14 13:51:06 work pulseaudio[11059]: [pulseaudio] alsa-util.c: format : S16_LE
Apr 14 13:51:06 work pulseaudio[11059]: [pulseaudio] alsa-util.c: subformat : STD
Apr 14 13:51:06 work pulseaudio[11059]: [pulseaudio] alsa-util.c: channels : 2
Apr 14 13:51:06 work pulseaudio[11059]: [pulseaudio] alsa-util.c: rate : 44100
Apr 14 13:51:06 work pulseaudio[11059]: [pulseaudio] alsa-util.c: exact rate : 44100 (44100/1)
Apr 14 13:51:06 work pulseaudio[11059]: [pulseaudio] alsa-util.c: msbits : 16
Apr 14 13:51:06 work pulseaudi...

Also, after I do:
echo 1 > /proc/asound/card0/pcm0p/xrun_debug

1 is not enough

http://www.alsa-project.org/main/index.php/XRUN_Debug

you need 11 to find out whether hardware pointer are correct on period update and how often lost interrupt occur compared with period update ?

# Enable basic debugging and dump stack, check hardware pointer on the period update
 # Usefull to just see, if PCM stream is stopped for a reason (usually wrong audio process timing from scheduler)
 # And to check the values from driver
 echo 11 > /proc/asound/card0/pcm0p/xrun_debu

I've tried 11, it's all spammed with messages to the level it gets suppressed. I'll give it a try tomorrow then. I just don't know which traces are relevant.

hardware pointer should be increased by one period on every period_update, the driver report lost interrupt when the elasped time is more than 1.5 period time

https://git.kernel.org/cgit/linux/kernel/git/tiwai/sound.git/tree/sound/core/pcm_lib.c

no_jiffies_check:
 if (delta > runtime->period_size + runtime->period_size / 2) {
  hw_ptr_error(substream, in_interrupt,
        "Lost interrupts?",
        "(stream=%i, delta=%ld, new_hw_ptr=%ld, old_hw_ptr=%ld)\n",
        substream->stream, (long)delta,
        (long)new_hw_ptr,
        (long)old_hw_ptr);
 }

pr 14 13:51:06 work pulseaudio[11059]: [pulseaudio] alsa-util.c: buffer_size : 192
Apr 14 13:51:06 work pulseaudio[11059]: [pulseaudio] alsa-util.c: period_size : 32
Apr 14 13:51:06 work pulseaudio[11059]: [pulseaudio] alsa-util.c: period_time : 725

the minimum period size of stereo s16le is 32 frames

you cannot get fragment time exactly 1ms ,

at this low latency, the sleep time will be less than 1ms if you are using two periods

Created attachment 115078
Kernel log

Here's the log. I've set tsched=0 and set 2 fragments, 2 ms each.

ALSA setup:

Apr 15 12:05:20 work pulseaudio[19799]: [pulseaudio] alsa-util.c: Soft volume PCM
Apr 15 12:05:20 work pulseaudio[19799]: [pulseaudio] alsa-util.c: Control: PCM Playback Volume
Apr 15 12:05:20 work pulseaudio[19799]: [pulseaudio] alsa-util.c: min_dB: -51
Apr 15 12:05:20 work pulseaudio[19799]: [pulseaudio] alsa-util.c: max_dB: 0
Apr 15 12:05:20 work pulseaudio[19799]: [pulseaudio] alsa-util.c: resolution: 256
Apr 15 12:05:20 work pulseaudio[19799]: [pulseaudio] alsa-util.c: Its setup is:
Apr 15 12:05:20 work pulseaudio[19799]: [pulseaudio] alsa-util.c: stream : PLAYBACK
Apr 15 12:05:20 work pulseaudio[19799]: [pulseaudio] alsa-util.c: access : MMAP_INTERLEAVED
Apr 15 12:05:20 work pulseaudio[19799]: [pulseaudio] alsa-util.c: format : S16_LE
Apr 15 12:05:20 work pulseaudio[19799]: [pulseaudio] alsa-util.c: subformat : STD
Apr 15 12:05:20 work pulseaudio[19799]: [pulseaudio] alsa-util.c: channels : 2
Apr 15 12:05:20 work pulseaudio[19799]: [pulseaudio] alsa-util.c: rate : 44100
Apr 15 12:05:20 work pulseaudio[19799]: [pulseaudio] alsa-util.c: exact rate : 44100 (44100/1)
Apr 15 12:05:20 work pulseaudio[19799]: [pulseaudio] alsa-util.c: msbits : 16
Apr 15 12:05:20 work pulseaudio[19799]: [pulseaudio] alsa-util.c: buffer_size : 192
Apr 15 12:05:20 work pulseaudio[19799]: [pulseaudio] alsa-util.c: period_size : 96
Apr 15 12:05:20 work pulseaudio[19799]: [pulseaudio] alsa-util.c: period_time : 2176
Apr 15 12:05:20 work pulseaudio[19799]: [pulseaudio] alsa-util.c: tstamp_mode : ENABLE
Apr 15 12:05:20 work pulseaudio[19799]: [pulseaudio] alsa-util.c: period_step : 1
Apr 15 12:05:20 work pulseaudio[19799]: [pulseaudio] alsa-util.c: avail_min : 96
Apr 15 12:05:20 work pulseaudio[19799]: [pulseaudio] alsa-util.c: period_event : 1
Apr 15 12:05:20 work pulseaudio[19799]: [pulseaudio] alsa-util.c: start_threshold : -1
Apr 15 12:05:20 work pulseaudio[19799]: [pulseaudio] alsa-util.c: stop_threshold : 6917529027641081856
Apr 15 12:05:20 work pulseaudio[19799]: [pulseaudio] alsa-util.c: silence_threshold: 0
Apr 15 12:05:20 work pulseaudio[19799]: [pulseaudio] alsa-util.c: silence_size : 0
Apr 15 12:05:20 work pulseaudio[19799]: [pulseaudio] alsa-util.c: boundary : 6917529027641081856
Apr 15 12:05:20 work pulseaudio[19799]: [pulseaudio] alsa-util.c: Slave: Hardware PCM card 0 'HDA Intel PCH' device 0 subdevice 0
Apr 15 12:05:20 work pulseaudio[19799]: [pulseaudio] alsa-util.c: Its setup is:
Apr 15 12:05:20 work pulseaudio[19799]: [pulseaudio] alsa-util.c: stream : PLAYBACK
Apr 15 12:05:20 work pulseaudio[19799]: [pulseaudio] alsa-util.c: access : MMAP_INTERLEAVED
Apr 15 12:05:20 work pulseaudio[19799]: [pulseaudio] alsa-util.c: format : S16_LE
Apr 15 12:05:20 work pulseaudio[19799]: [pulseaudio] alsa-util.c: subformat : STD
Apr 15 12:05:20 work pulseaudio[19799]: [pulseaudio] alsa-util.c: channels : 2
Apr 15 12:05:20 work pulseaudio[19799]: [pulseaudio] alsa-util.c: rate : 44100
Apr 15 12:05:20 work pulsea...

Updated my EFI, PA has the same settings:

[ 156.151092] ALSA: PCM: [Q] Lost interrupts?: (stream=0, delta=161, new_hw_ptr=2517145, old_hw_ptr=2516984)
[ 156.151099] CPU: 0 PID: 2399 Comm: chrome Not tainted 3.19.0-pf2+ #1
[ 156.151100] Hardware name: System manufacturer System Product Name/P8H61-M LX2, BIOS 0605 05/09/2013
[ 156.151102] 0000000000000000 0000000000000019 ffffffff8154b50a ffff8800948ab400
[ 156.151105] ffffffffa062e10f ffff8801ae5c1a80 0000000000213766 ffff8801ae5c1ac0
[ 156.151107] ffffffff815508fc ffff880235e4cda0 0000000000000000 0000000100023a7d
[ 156.151110] Call Trace:
[ 156.151112] <IRQ> [<ffffffff8154b50a>] ? dump_stack+0x4a/0x74
[ 156.151131] [<ffffffffa062e10f>] ? snd_pcm_update_hw_ptr0+0x40f/0x8d0 [snd_pcm]
[ 156.151134] [<ffffffff815508fc>] ? _raw_spin_unlock_irqrestore+0x1c/0x40
[ 156.151138] [<ffffffff81090b94>] ? resched_curr+0x24/0xf0
[ 156.151142] [<ffffffffa062e63a>] ? snd_pcm_period_elapsed+0x6a/0xe0 [snd_pcm]
[ 156.151146] [<ffffffffa0582f2b>] ? azx_interrupt+0x10b/0x1c0 [snd_hda_controller]
[ 156.151150] [<ffffffff810c7f6d>] ? handle_irq_event_percpu+0x2d/0x1e0
[ 156.151153] [<ffffffff810c8159>] ? handle_irq_event+0x39/0x60
[ 156.151155] [<ffffffff810cafd1>] ? handle_edge_irq+0x91/0x150
[ 156.151159] [<ffffffff81017678>] ? handle_irq+0x18/0x30
[ 156.151161] [<ffffffff81016dfd>] ? do_IRQ+0x4d/0xf0
[ 156.151164] [<ffffffff81551fed>] ? common_interrupt+0x6d/0x6d
[ 156.151165] <EOI> [<ffffffff8155126d>] ? system_call_fastpath+0x16/0x1b
[ 162.888555] ALSA: PCM: [Q] Lost interrupts?: (stream=0, delta=161, new_hw_ptr=2814073, old_hw_ptr=2813912)
[ 162.888562] CPU: 0 PID: 0 Comm: swapper/0 Not tainted 3.19.0-pf2+ #1
[ 162.888564] Hardware name: System manufacturer System Product Name/P8H61-M LX2, BIOS 0605 05/09/2013
[ 162.888566] 0000000000000000 0000000000000079 ffffffff8154b50a ffff8800948ab400
[ 162.888570] ffffffffa062e10f 0000000000000000 ffff88023fa0e4c0 0000000000000000
[ 162.888582] ffff88023fa03ea4 00000001000254d4 0000000000000000 00000001000254ca
[ 162.888585] Call Trace:
[ 162.888587] <IRQ> [<ffffffff8154b50a>] ? dump_stack+0x4a/0x74
[ 162.888609] [<ffffffffa062e10f>] ? snd_pcm_update_hw_ptr0+0x40f/0x8d0 [snd_pcm]
[ 162.888614] [<ffffffffa062e63a>] ? snd_pcm_period_elapsed+0x6a/0xe0 [snd_pcm]
[ 162.888617] [<ffffffffa0582f2b>] ? azx_interrupt+0x10b/0x1c0 [snd_hda_controller]
[ 162.888623] [<ffffffff810c7f6d>] ? handle_irq_event_percpu+0x2d/0x1e0
[ 162.888626] [<ffffffff810c8159>] ? handle_irq_event+0x39/0x60
[ 162.888628] [<ffffffff810cafd1>] ? handle_edge_irq+0x91/0x150
[ 162.888632] [<ffffffff81017678>] ? handle_irq+0x18/0x30
[ 162.888635] [<ffffffff81016dfd>] ? do_IRQ+0x4d/0xf0
[ 162.888638] [<ffffffff81551fed>] ? common_interrupt+0x6d/0x6d
[ 162.888639] <EOI> [<ffffffff81427f99>] ? cpuidle_enter_state+0x59/0x1a0
[ 162.888644] [<ffffffff81427f89>] ? cpuidle_enter_state+0x49/0x1a0
[ 162.888648] [<ffffffff810a4599>] ? cpu_startup_entry+0x489/0x4f0
[ 162.888652] [<ffffffff818edf69>] ? start_kernel+0x47b/0x486
[ 162.888654] [<ffffffff818ed120>] ? early_idt_handlers+0x120/0x120
[ 162.888656] [<ffffffff818ed120>] ? early_id...

seem dump stack is not useful

just need 1+4+8 = 13

 1 Basic debugging - show xruns in ksyslog interface
 2 Dump stack - dump stack for basic debugging
 4 Jiffies check - compare the position with kernel jiffies (a sort of in-kernel monotonic clock),
     show what's changed when basic debugging is enabled
 8 Dump positions on each period update call
 16 Dump positions on each hardware pointer update call
 32 Enable logging of last 10 ring buffer positions
 64 Show the last 10 ring buffer position only once (when first error situation occured)

Nothing seems to be printed with debug = 13:
[14559.554693] ALSA: PCM: [Q] Lost interrupts?: (stream=0, delta=161, new_hw_ptr=702553, old_hw_ptr=702392)
[14564.895847] ALSA: PCM: [Q] Lost interrupts?: (stream=0, delta=161, new_hw_ptr=937945, old_hw_ptr=937784)
[14565.941444] ALSA: PCM: [Q] Lost interrupts?: (stream=0, delta=161, new_hw_ptr=984025, old_hw_ptr=983864)
[14573.145037] ALSA: PCM: [Q] Lost interrupts?: (stream=0, delta=161, new_hw_ptr=1301497, old_hw_ptr=1301336)
[14574.635010] ALSA: PCM: [Q] Lost interrupts?: (stream=0, delta=161, new_hw_ptr=1367161, old_hw_ptr=1367000)
[14577.096462] ALSA: PCM: [Q] Lost interrupts?: (stream=0, delta=161, new_hw_ptr=1475641, old_hw_ptr=1475480)
[14586.796312] ALSA: PCM: [Q] Lost interrupts?: (stream=0, delta=161, new_hw_ptr=1903129, old_hw_ptr=1902968)
[14586.992402] ALSA: PCM: [Q] Lost interrupts?: (stream=0, delta=161, new_hw_ptr=1911769, old_hw_ptr=1911608)
[14594.026044] ALSA: PCM: [Q] Lost interrupts?: (stream=0, delta=161, new_hw_ptr=2221753, old_hw_ptr=2221592)
[14595.953870] ALSA: PCM: [Q] Lost interrupts?: (stream=0, delta=169, new_hw_ptr=2306713, old_hw_ptr=2306544)
[14596.659610] ALSA: PCM: [Q] Lost interrupts?: (stream=0, delta=161, new_hw_ptr=2337817, old_hw_ptr=2337656)
[14596.685752] ALSA: PCM: [Q] Lost interrupts?: (stream=0, delta=161, new_hw_ptr=2338969, old_hw_ptr=2338808)
[14602.107478] ALSA: PCM: [Q] Lost interrupts?: (stream=0, delta=185, new_hw_ptr=2577913, old_hw_ptr=2577728)
[14603.678073] ALSA: PCM: [Q] Lost interrupts?: (stream=0, delta=161, new_hw_ptr=2647129, old_hw_ptr=2646968)
[14607.444299] ALSA: PCM: [Q] Lost interrupts?: (stream=0, delta=161, new_hw_ptr=2813113, old_hw_ptr=2812952)
[14608.614012] ALSA: PCM: [Q] Lost interrupts?: (stream=0, delta=185, new_hw_ptr=2864665, old_hw_ptr=2864480)
[14609.178195] ALSA: PCM: [Q] Lost interrupts?: (stream=0, delta=169, new_hw_ptr=2889529, old_hw_ptr=2889360)
[14614.619587] ALSA: PCM: [Q] Lost interrupts?: (stream=0, delta=161, new_hw_ptr=3129337, old_hw_ptr=3129176)
[14616.410149] ALSA: PCM: [Q] Lost interrupts?: (stream=0, delta=161, new_hw_ptr=3208249, old_hw_ptr=3208088)
[14616.593118] ALSA: PCM: [Q] Lost interrupts?: (stream=0, delta=161, new_hw_ptr=3216313, old_hw_ptr=3216152)
[14621.289473] ALSA: PCM: [Q] Lost interrupts?: (stream=0, delta=161, new_hw_ptr=3423289, old_hw_ptr=3423128)
[14621.315617] ALSA: PCM: [Q] Lost interrupts?: (stream=0, delta=161, new_hw_ptr=3424441, old_hw_ptr=3424280)
[14622.783780] ALSA: PCM: [Q] Lost interrupts?: (stream=0, delta=161, new_hw_ptr=3489145, old_hw_ptr=3488984)

Enable basic debugging, do jiffies check and dump position on each period and hardware pointer update calls
 # Usefull when the lowlevel (specific) hardware driver is somehow broken
 echo 29 > /proc/asound/card0/pcm0p/xrun_debug

Still nothing:

[ 1469.264611] ALSA: PCM: [Q] Lost interrupts?: (stream=0, delta=161, new_hw_ptr=4954969, old_hw_ptr=4954808)
[ 1469.340845] ALSA: PCM: [Q] Lost interrupts?: (stream=0, delta=169, new_hw_ptr=4958329, old_hw_ptr=4958160)
[ 1470.946188] ALSA: PCM: [Q] Lost interrupts?: (stream=0, delta=153, new_hw_ptr=5029073, old_hw_ptr=5028920)
[ 1471.872164] ALSA: PCM: [Q] Lost interrupts?: (stream=0, delta=168, new_hw_ptr=5069888, old_hw_ptr=5069720)
[ 1473.533990] ALSA: PCM: [Q] Lost interrupts?: (stream=0, delta=153, new_hw_ptr=5143121, old_hw_ptr=5142968)
[ 1475.176618] ALSA: PCM: [Q] Lost interrupts?: (stream=0, delta=176, new_hw_ptr=5215520, old_hw_ptr=5215344)
[ 1477.775171] ALSA: PCM: [Q] Lost interrupts?: (stream=0, delta=161, new_hw_ptr=5330041, old_hw_ptr=5329880)
[ 1478.241325] ALSA: PCM: [Q] Lost interrupts?: (stream=0, delta=161, new_hw_ptr=5350585, old_hw_ptr=5350424)
[ 1479.169273] ALSA: PCM: [Q] Lost interrupts?: (stream=0, delta=161, new_hw_ptr=5391481, old_hw_ptr=5391320)
[ 1479.835845] ALSA: PCM: [Q] Lost interrupts?: (stream=0, delta=153, new_hw_ptr=5420857, old_hw_ptr=5420704)
[ 1480.471852] ALSA: PCM: [Q] Lost interrupts?: (stream=0, delta=161, new_hw_ptr=5448889, old_hw_ptr=5448728)
[ 1480.903183] ALSA: PCM: [Q] Lost interrupts?: (stream=0, delta=161, new_hw_ptr=5467897, old_hw_ptr=5467736)
[ 1481.815867] ALSA: PCM: [Q] Lost interrupts?: (stream=0, delta=161, new_hw_ptr=5508121, old_hw_ptr=5507960)
[ 1481.931274] ALSA: PCM: [Q] Lost interrupts?: (stream=0, delta=153, new_hw_ptr=5513201, old_hw_ptr=5513048)
[ 1482.397507] ALSA: PCM: [Q] Lost interrupts?: (stream=0, delta=153, new_hw_ptr=5533753, old_hw_ptr=5533600)
[ 1483.181608] ALSA: PCM: [Q] Lost interrupts?: (stream=0, delta=153, new_hw_ptr=5568305, old_hw_ptr=5568152)
[ 1485.830481] ALSA: PCM: [Q] Lost interrupts?: (stream=0, delta=169, new_hw_ptr=5685049, old_hw_ptr=5684880)
[ 1486.366331] ALSA: PCM: [Q] Lost interrupts?: (stream=0, delta=161, new_hw_ptr=5708665, old_hw_ptr=5708504)
[ 1486.876226] ALSA: PCM: [Q] Lost interrupts?: (stream=0, delta=160, new_hw_ptr=5731136, old_hw_ptr=5730976)

# cat /proc/asound/card0/pcm0p/xrun_debug
29

So I've done some research. This article describes the timer model and how ALSA works in regards of periods/fragments and software/hardware buffers: http://0pointer.de/blog/projects/pulse-glitch-free.html

According to the article, PA works in two modes, with tsched=0 it's the old IRQ-driven mode as ALSA does and it heavily relies to the fragments number and size. Hence it gets ALSA underruns if the app is too slow to fill the buffer. It happens to my work PC sometime because it isn't too fast (model name: Intel(R) Pentium(R) CPU G620 @ 2.60GHz) and I mostly listen to music in Chrome (HTML5 audio). Chrome has the latency of ~65 ms now. It's quite feasible that some program would occupy the CPU for this much time so I'd have a skip/underrun. In case of tsched=0 there's nothing we can do as period/buffer size is set up on startup and basically can't be changed in runtime.

When tsched=1 or not specified (defaults to 1) PA sets up an ALSA buffer of 2 seconds long with two periods of 1 second each. This way it doesn't underrun in ALSA but rather underruns in PA itself. This code is responsible for tweaking the watermark and latency: https://github.com/pulseaudio/pulseaudio/blob/master/src/modules/alsa/alsa-sink.c#L326

The problem here is that watermark can go in both directions, up and down, while latency can only grow until the sink is reset (recreated). This actually means that if some particular program has chosen too little latency and had several underruns because of that, THE WHOLE LOT OF OTHER PROGRAMS now will suffer bad latency as well! And there's no other way to lower it back other than restarting PA itself together with all its clients or when PA gets unsuspended ( https://github.com/pulseaudio/pulseaudio/blob/master/src/modules/alsa/alsa-sink.c#L1021 ).

I haven't found a way to setup a default minimal latency so that if I know that my system isn't capable to deliver 4 ms, I can set it to 16 instead of having 0.5 ms and several underruns just to let PA get to that latency by itself. It seems to me that this minimal latency is just hardcoded ( https://github.com/pulseaudio/pulseaudio/blob/master/src/pulsecore/sink.c#L54 ) and there are no tools to call pa_sink_set_latency_range ( https://github.com/pulseaudio/pulseaudio/blob/master/src/pulsecore/sink.c#L3091 )

And also, I repeat, launching pavucontrol for the first time and sometimes pacmd list-sinks causes stuttering on my work system (works ok at home but there I have i7-2600 and PCI SB Live 7.1). I don't know how and why but they seem to block PA somewhere so that Chrome can't sink its audio to it in time and hence we get an underrun, latency increase and the bad mood. I dunno, maybe I have to file this pavucontrol bug separately.

https://www.google.com/patents/US20100131783

FIG. 2 illustrates an exemplary FIFO which has a FIFO size of 192 bytes, and a
threshold value of 128 bytes.

 Taking 48 kHz sample rate, 2 channels each having 16 bits (or 2 bytes) for example, each frame thus contains 4 bytes of data, wherein each frame is regarded as a “data unit of transportation.” Whenever the amount of stream data in the FIFO is less than 128 bytes (i.e., the threshold), the HDAC 15 will issue a bus mater cycle. As each frame is transported in an interval time of 20.83 micro second (μs) (=1/(48×103)), which is regarded as a “time unit of transportation,” the 128 bytes therefore can keep 32 frames (=128/4) of data for about 666 micro second (=32×20.83) without under run.

you need to use 32bits or more channels, higher rate to get 0.5ms latency

0.5 ms is just what PA reports as the minimal latency. I don't need it to be this small, I just don't want it to grow up to 100 ms without the possibility to automatically drop it back to normal. I suppose it's not possible to make PA work with fragments as ALSA does. As I understand from the Lennart's article, the latency in ALSA is the size of period ±something. For PA it's the size of fragment * number of fragments as it reports this as the minimal latency in pacmd list-sinks. It's also very noticeable when you use realtime apps like LMMS or games.

However, it's not true for dmix. I play a file with everything at default on my home PC with SB Live 7.1 (at work the overall picture is more or less the same), here's what I have:

> aplay -v /usr/share/sounds/alsa/Front_Center.wav
Playing WAVE '/usr/share/sounds/alsa/Front_Center.wav' : Signed 16 bit Little Endian, Rate 48000 Hz, Mono
Plug PCM: Route conversion PCM (sformat=S32_LE)
  Transformation table:
    0 <- 0
    1 <- 0
Its setup is:
  stream : PLAYBACK
  access : RW_INTERLEAVED
  format : S16_LE
  subformat : STD
  channels : 1
  rate : 48000
  exact rate : 48000 (48000/1)
  msbits : 16
  buffer_size : 8192
  period_size : 1024
  period_time : 21333
  tstamp_mode : NONE
  period_step : 1
  avail_min : 1024
  period_event : 0
  start_threshold : 8192
  stop_threshold : 8192
  silence_threshold: 0
  silence_size : 0
  boundary : 4611686018427387904
Slave: Direct Stream Mixing PCM
Its setup is:
  stream : PLAYBACK
  access : MMAP_INTERLEAVED
  format : S32_LE
  subformat : STD
  channels : 2
  rate : 48000
  exact rate : 48000 (48000/1)
  msbits : 32
  buffer_size : 8192
  period_size : 1024
  period_time : 21333
  tstamp_mode : NONE
  period_step : 1
  avail_min : 1024
  period_event : 0
  start_threshold : 8192
  stop_threshold : 8192
  silence_threshold: 0
  silence_size : 0
  boundary : 4611686018427387904
Hardware PCM card 0 'CA0106' device 0 subdevice 0
Its setup is:
  stream : PLAYBACK
  access : MMAP_INTERLEAVED
  format : S32_LE
  subformat : STD
  channels : 2
  rate : 48000
  exact rate : 48000 (48000/1)
  msbits : 32
  buffer_size : 8192
  period_size : 1024
  period_time : 21333
  tstamp_mode : ENABLE
  period_step : 1
  avail_min : 1024
  period_event : 0
  start_threshold : 1
  stop_threshold : 4611686018427387904
  silence_threshold: 0
  silence_size : 4611686018427387904
  boundary : 4611686018427387904
  appl_ptr : 0
  hw_ptr : 0

The buffer size is 8192 frames which is8192 / 48000 == 0.17066 s == 170 ms but there's no noticeable latency at all. If I setup PA not to use tsched and set 8 fragments of 21 ms each (almost exactly as in dmix), I have this setup then:

Apr 16 19:16:17 homecomp pulseaudio[6121]: [pulseaudio] alsa-util.c: Hardware PCM card 0 'CA0106' device 0 subdevice 0
Apr 16 19:16:17 homecomp pulseaudio[6121]: [pulseaudio] alsa-util.c: Its setup is:
Apr 16 19:16:17 homecomp pulseaudio[6121]: [pulseaudio] alsa-util.c: stream : PLAYBACK
Apr 16 19:16:17 homecomp pulseaudio[6121]...

as pulseaudio use snd_pcm_rewind() which require the sound card report accurate hwptr position than those sound card which report hwptr position at period bounary when interrupt occur

the difference between hda-intel and your ca0106 is the granularity of the pointer callback

https://git.kernel.org/cgit/linux/kernel/git/tiwai/sound.git/tree/include/linux/dmaengine.h

/**
 * enum dma_residue_granularity - Granularity of the reported transfer residue
 * @DMA_RESIDUE_GRANULARITY_DESCRIPTOR: Residue reporting is not support. The
 * DMA channel is only able to tell whether a descriptor has been completed or
 * not, which means residue reporting is not supported by this channel. The
 * residue field of the dma_tx_state field will always be 0.
 * @DMA_RESIDUE_GRANULARITY_SEGMENT: Residue is updated after each successfully
 * completed segment of the transfer (For cyclic transfers this is after each
 * period). This is typically implemented by having the hardware generate an
 * interrupt after each transferred segment and then the drivers updates the
 * outstanding residue by the size of the segment. Another possibility is if
 * the hardware supports scatter-gather and the segment descriptor has a field
 * which gets set after the segment has been completed. The driver then counts
 * the number of segments without the flag set to compute the residue.
 * @DMA_RESIDUE_GRANULARITY_BURST: Residue is updated after each transferred
 * burst. This is typically only supported if the hardware has a progress
 * register of some sort (E.g. a register with the current read/write address
 * or a register with the amount of bursts/beats/bytes that have been
 * transferred or still need to be transferred).
 */

hda-intel can report DMA_RESIDUE_GRANULARITY_BURST

seem both read hwptr from hardware register

can your ca0106 report DMA_RESIDUE_GRANULARITY_SEGMENT or DMA_RESIDUE_GRANULARITY_BURST ?

https://git.kernel.org/cgit/linux/kernel/git/tiwai/sound.git/tree/sound/pci/ca0106/ca0106_main.c

static snd_pcm_uframes_t
snd_ca0106_pcm_pointer_playback(struct snd_pcm_substream *substream)
{
 struct snd_ca0106 *emu = snd_pcm_substream_chip(substream);
 struct snd_pcm_runtime *runtime = substream->runtime;
 struct snd_ca0106_pcm *epcm = runtime->private_data;
 unsigned int ptr, prev_ptr;
 int channel = epcm->channel_id;
 int timeout = 10;

 if (!epcm->running)
  return 0;

 prev_ptr = -1;
 do {
  ptr = snd_ca0106_ptr_read(emu, PLAYBACK_LIST_PTR, channel);
  ptr = (ptr >> 3) * runtime->period_size;
  ptr += bytes_to_frames(runtime,
   snd_ca0106_ptr_read(emu, PLAYBACK_POINTER, channel));
  if (ptr >= runtime->buffer_size)
   ptr -= runtime->buffer_size;
  if (prev_ptr == ptr)
   return ptr;
  prev_ptr = ptr;
 } while (--timeout);
 dev_warn(emu->card->dev, "ca0106: unstable DMA pointer!\n");
 return 0;
}

https://git.kernel.org/cgit/linux/kernel/git/tiwai/sound.git/tree/sound/pci/hda/hda_controller.c

static snd_pcm_uframes_t azx_pcm_pointer(struct snd_pcm_substream *substream)
{
 struct azx_pcm *apcm = snd_pcm_substream_chip(substream);
 struct azx *chip = apcm->chip;
 struct azx_dev *azx_dev = get_azx_dev(substream);
 return bytes_to_frames(subs...

http://mailman.alsa-project.org/pipermail/alsa-devel/2014-September/081501.html

you need to modify Alexander's pcm_avail.c to find out how accurate hwptr position can be reported by your ca0106 hw device since his program hardcode to use 44100Hz which is not supported by your ca0106

if the result if alexander pcm_avail.c show available increment by period size

this means you need to use more than two fragments and increase rewind_safeguard

http://cgit.freedesktop.org/pulseaudio/pulseaudio/commit/?id=4df443bbe682055a41e7c2248877dcc7682a69b8

16 19:16:17 homecomp pulseaudio[6121]: [pulseaudio] alsa-util.c: format : S32_LE
Apr 16 19:16:17 homecomp pulseaudio[6121]: [pulseaudio] alsa-util.c: subformat : STD
Apr 16 19:16:17 homecomp pulseaudio[6121]: [pulseaudio] alsa-util.c: channels : 2
Apr 16 19:16:17 homecomp pulseaudio[6121]: [pulseaudio] alsa-util.c: rate : 48000
Apr 16 19:16:17 homecomp pulseaudio[6121]: [pulseaudio] alsa-util.c: exact rate : 48000 (48000/1)
Apr 16 19:16:17 homecomp pulseaudio[6121]: [pulseaudio] alsa-util.c: msbits : 32
Apr 16 19:16:17 homecomp pulseaudio[6121]: [pulseaudio] alsa-util.c: buffer_size : 8064
Apr 16 19:16:17 homecomp pulseaudio[6121]: [pulseaudio] alsa-util.c: period_size : 1008
Apr 16 19:16:17 homecomp pulseaudio[6121]: [pulseaudio] alsa-util.c: period_time : 21000

https://git.kernel.org/cgit/linux/kernel/git/tiwai/sound.git/tree/sound/pci/ca0106/ca0106_main.c

 if ((err = snd_pcm_hw_constraint_integer(runtime, SNDRV_PCM_HW_PARAM_PERIODS)) < 0)
                return err;
 if ((err = snd_pcm_hw_constraint_step(runtime, 0, SNDRV_PCM_HW_PARAM_PERIOD_BYTES, 64)) < 0)
                return err;

although ca0106 has smaller minimum period bytes than hda intel

the granularity is not depend on minimum period size but only on how often sound card can report hwptr in realtime

Some more info. On my new laptop that also has a VIA sound chipset I managed to greatly leverage the problem by installing the low-latency Ubuntu kernel. I have Ubuntu MATE 14.04 on it so it was effortless. Unfortunately, for (presumably) performance reasons it doesn't have CONFIG_SND_PCM_XRUN_DEBUG enabled so I can't see if it also misses interrupts. However, on the default stock kernel which has this option it misses interrupts indeed. I tried various position_fix and enable_msi values and nothing helped. I had underruns in the log while doing usual things like opening sites, now on the low-latency kernel it's all good even on PA's timer-based scheduling.

I can only guess but it could be because the CPU has only two cores and sometimes it can't schedule an interrupt in time. The low-latency kernel has 1000 Hz timer compared to 250 Hz in the default one. It also has various NO_HZ_* options enabled. I'll try two options on Monday with my own kernel for Debian: one would be using the BFS scheduler and another one will feature CONFIG_NO_HZ_FULL_ALL and alike options which are disabled when BFS is used. I'll check if either of them will help with the missed interrupts.

The problem as I see it is that my work PC and this laptop isn't powerful enough to server IRQs in time. They both have VIA sound although a bit different models and 2 core CPUs. My home PC has 4 cores that are also more powerful. I tried to output some sound via PA to its Realtek ALC889 card and enabled xrun_debug. There were no messages about lost interrupts and I'm using the same kernel that's used on the work PC. So the different behavior is either because of different codecs/chipsets or CPUs.

https://git.kernel.org/cgit/linux/kernel/git/tiwai/sound.git/tree/Documentation/sound/alsa/Procfile.txt

http://mailman.alsa-project.org/pipermail/alsa-devel/2014-November/083495.html

you need to ask the author how to debug your case "Lost Interrupt!"

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