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 annoying having audio skip all the time.
> > ( 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 [details] 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 [details] 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 [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.
(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 [details] 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 avail_max : 281 underrun!!! (at least 3.647 ms long) Status: state : XRUN trigger_time: 3360.9384022 tstamp : 3360.13029349 delay : 0 avail : 200 avail_max : 200 underrun!!! (at least 1.095 ms long) Status: state : XRUN trigger_time: 3361.11945732 tstamp : 3361.13039182 delay : 0 avail : 200 avail_max : 200 underrun!!! (at least 3.016 ms long) Status: state : XRUN trigger_time: 3361.132006217 tstamp : 3361.135020659 delay : 0 avail : 200 avail_max : 200 underrun!!! (at least 0.352 ms long) Status: state : XRUN trigger_time: 3361.465478201 tstamp : 3361.465829023 delay : 0 avail : 200 avail_max : 200 underrun!!! (at least 2.799 ms long) Status: state : XRUN trigger_time: 3361.502227029 tstamp : 3361.505024503 delay : 0 avail : 200 avail_max : 200 underrun!!! (at least 0.019 ms long) Status: state : XRUN trigger_time: 3361.513310022 tstamp : 3361.513327710 delay : 0 avail : 200 avail_max : 200 ^CAborted by signal Interrupt... 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)
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 Apr 09 11:56:10 work pulseaudio[9718]: [alsa-sink-VT1708S Analog] alsa-util.c: buffer_size : 704 Apr 09 11:56:10 work pulseaudio[9718]: [alsa-sink-VT1708S Analog] alsa-util.c: period_size : 352 Apr 09 11:56:10 work pulseaudio[9718]: [alsa-sink-VT1708S Analog] alsa-util.c: period_time : 7981 Apr 09 11:56:10 work pulseaudio[9718]: [alsa-sink-VT1708S Analog] alsa-util.c: tstamp_mode : ENABLE Apr 09 11:56:10 work pulseaudio[9718]: [alsa-sink-VT1708S Analog] alsa-util.c: period_step : 1 Apr 09 11:56:10 work pulseaudio[9718]: [alsa-sink-VT1708S Analog] alsa-util.c: avail_min : 352 Apr 09 11:56:10 work pulseaudio[9718]: [alsa-sink-VT1708S Analog] alsa-util.c: period_event : 1 Apr 09 11:56:10 work pulseaudio[9718]: [alsa-sink-VT1708S Analog] alsa-util.c: start_threshold : -1 Apr 09 11:56:10 work pulseaudio[9718]: [alsa-sink-VT1708S Analog] alsa-util.c: stop_threshold : 6341068275337658368 Apr 09 11:56:10 work pulseaudio[9718]: [alsa-sink-VT1708S Analog] alsa-util.c: silence_threshold: 0 Apr 09 11:56:10 work pulseaudio[9718]: [alsa-sink-VT1708S Analog] alsa-util.c: silence_size : 0 Apr 09 11:56:10 work pulseaudio[9718]: [alsa-sink-VT1708S Analog] alsa-util.c: boundary : 6341068275337658368 Apr 09 11:56:10 work pulseaudio[9718]: [alsa-sink-VT1708S Analog] alsa-util.c: Slave: Hardware PCM card 0 'HDA Intel PCH' device 0 subdevice 0 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 Apr 09 11:56:10 work pulseaudio[9718]: [alsa-sink-VT1708S Analog] alsa-util.c: buffer_size : 704 Apr 09 11:56:10 work pulseaudio[9718]: [alsa-sink-VT1708S Analog] alsa-util.c: period_size : 352 Apr 09 11:56:10 work pulseaudio[9718]: [alsa-sink-VT1708S Analog] alsa-util.c: period_time : 7981 Apr 09 11:56:10 work pulseaudio[9718]: [alsa-sink-VT1708S Analog] alsa-util.c: tstamp_mode : ENABLE Apr 09 11:56:10 work pulseaudio[9718]: [alsa-sink-VT1708S Analog] alsa-util.c: period_step : 1 Apr 09 11:56:10 work pulseaudio[9718]: [alsa-sink-VT1708S Analog] alsa-util.c: avail_min : 352 Apr 09 11:56:10 work pulseaudio[9718]: [alsa-sink-VT1708S Analog] alsa-util.c: period_event : 1 Apr 09 11:56:10 work pulseaudio[9718]: [alsa-sink-VT1708S Analog] alsa-util.c: start_threshold : -1 Apr 09 11:56:10 work pulseaudio[9718]: [alsa-sink-VT1708S Analog] alsa-util.c: stop_threshold : 6341068275337658368 Apr 09 11:56:10 work pulseaudio[9718]: [alsa-sink-VT1708S Analog] alsa-util.c: silence_threshold: 0 Apr 09 11:56:10 work pulseaudio[9718]: [alsa-sink-VT1708S Analog] alsa-util.c: silence_size : 0 Apr 09 11:56:10 work pulseaudio[9718]: [alsa-sink-VT1708S Analog] alsa-util.c: boundary : 6341068275337658368 Apr 09 11:56:10 work pulseaudio[9718]: [alsa-sink-VT1708S Analog] alsa-util.c: appl_ptr : 80123792 Apr 09 11:56:10 work pulseaudio[9718]: [alsa-sink-VT1708S Analog] alsa-util.c: hw_ptr : 80135633 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] alsa-util.c: snd_pcm_delay() returned a value that is exceptionally large: -41248 bytes (-233 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 Apr 09 11:56:10 work pulseaudio[9718]: [alsa-sink-VT1708S Analog] alsa-util.c: buffer_size : 704 Apr 09 11:56:10 work pulseaudio[9718]: [alsa-sink-VT1708S Analog] alsa-util.c: period_size : 352 Apr 09 11:56:10 work pulseaudio[9718]: [alsa-sink-VT1708S Analog] alsa-util.c: period_time : 7981 Apr 09 11:56:10 work pulseaudio[9718]: [alsa-sink-VT1708S Analog] alsa-util.c: tstamp_mode : ENABLE Apr 09 11:56:10 work pulseaudio[9718]: [alsa-sink-VT1708S Analog] alsa-util.c: period_step : 1 Apr 09 11:56:10 work pulseaudio[9718]: [alsa-sink-VT1708S Analog] alsa-util.c: avail_min : 352 Apr 09 11:56:10 work pulseaudio[9718]: [alsa-sink-VT1708S Analog] alsa-util.c: period_event : 1 Apr 09 11:56:10 work pulseaudio[9718]: [alsa-sink-VT1708S Analog] alsa-util.c: start_threshold : -1 Apr 09 11:56:10 work pulseaudio[9718]: [alsa-sink-VT1708S Analog] alsa-util.c: stop_threshold : 6341068275337658368 Apr 09 11:56:10 work pulseaudio[9718]: [alsa-sink-VT1708S Analog] alsa-util.c: silence_threshold: 0 Apr 09 11:56:10 work pulseaudio[9718]: [alsa-sink-VT1708S Analog] alsa-util.c: silence_size : 0 Apr 09 11:56:10 work pulseaudio[9718]: [alsa-sink-VT1708S Analog] alsa-util.c: boundary : 6341068275337658368 Apr 09 11:56:10 work pulseaudio[9718]: [alsa-sink-VT1708S Analog] alsa-util.c: Slave: Hardware PCM card 0 'HDA Intel PCH' device 0 subdevice 0 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 Apr 09 11:56:10 work pulseaudio[9718]: [alsa-sink-VT1708S Analog] alsa-util.c: buffer_size : 704 Apr 09 11:56:10 work pulseaudio[9718]: [alsa-sink-VT1708S Analog] alsa-util.c: period_size : 352 Apr 09 11:56:10 work pulseaudio[9718]: [alsa-sink-VT1708S Analog] alsa-util.c: period_time : 7981 Apr 09 11:56:10 work pulseaudio[9718]: [alsa-sink-VT1708S Analog] alsa-util.c: tstamp_mode : ENABLE Apr 09 11:56:10 work pulseaudio[9718]: [alsa-sink-VT1708S Analog] alsa-util.c: period_step : 1 Apr 09 11:56:10 work pulseaudio[9718]: [alsa-sink-VT1708S Analog] alsa-util.c: avail_min : 352 Apr 09 11:56:10 work pulseaudio[9718]: [alsa-sink-VT1708S Analog] alsa-util.c: period_event : 1 Apr 09 11:56:10 work pulseaudio[9718]: [alsa-sink-VT1708S Analog] alsa-util.c: start_threshold : -1 Apr 09 11:56:10 work pulseaudio[9718]: [alsa-sink-VT1708S Analog] alsa-util.c: stop_threshold : 6341068275337658368 Apr 09 11:56:10 work pulseaudio[9718]: [alsa-sink-VT1708S Analog] alsa-util.c: silence_threshold: 0 Apr 09 11:56:10 work pulseaudio[9718]: [alsa-sink-VT1708S Analog] alsa-util.c: silence_size : 0 Apr 09 11:56:10 work pulseaudio[9718]: [alsa-sink-VT1708S Analog] alsa-util.c: boundary : 6341068275337658368 Apr 09 11:56:10 work pulseaudio[9718]: [alsa-sink-VT1708S Analog] alsa-util.c: appl_ptr : 80130832 Apr 09 11:56:10 work pulseaudio[9718]: [alsa-sink-VT1708S Analog] alsa-util.c: hw_ptr : 80141265 Apr 09 11:56:10 work pulseaudio[9718]: [alsa-sink-VT1708S Analog] ratelimit.c: 14 events suppressed Apr 09 11:56:10 work pulseaudio[9718]: [alsa-sink-VT1708S Analog] alsa-sink.c: Underrun! 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 = 10117 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...
(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 [details] 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 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: appl_ptr : 0 Apr 10 09:46:52 work pulseaudio[5161]: [pulseaudio] alsa-util.c: hw_ptr : 0 Why does period size lack 4 bytes to be exactly 1 second long?
(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 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: appl_ptr : 0 Apr 14 13:51:06 work pulseaudio[11059]: [pulseaudio] alsa-util.c: hw_ptr : 0
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 [details] 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 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: appl_ptr : 0 Apr 15 12:05:20 work pulseaudio[19799]: [pulseaudio] alsa-util.c: hw_ptr : 0
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_idt_handlers+0x120/0x120 [ 162.888658] [<ffffffff818ed60d>] ? x86_64_start_kernel+0x150/0x15f [ 170.116076] ALSA: PCM: [Q] Lost interrupts?: (stream=0, delta=161, new_hw_ptr=3132601, old_hw_ptr=3132440) [ 170.116083] CPU: 0 PID: 2290 Comm: chrome Not tainted 3.19.0-pf2+ #1 [ 170.116084] Hardware name: System manufacturer System Product Name/P8H61-M LX2, BIOS 0605 05/09/2013 [ 170.116086] 0000000000000000 0000000000000079 ffffffff8154b50a ffff8800948ab400 [ 170.116088] ffffffffa062e10f 0000000000000000 ffff88023fa0e4c0 0000000000000000 [ 170.116091] ffff88023fa03ea4 ffff88020a8c6780 0000000000000000 0000000100027101 [ 170.116093] Call Trace: [ 170.116094] <IRQ> [<ffffffff8154b50a>] ? dump_stack+0x4a/0x74 [ 170.116114] [<ffffffffa062e10f>] ? snd_pcm_update_hw_ptr0+0x40f/0x8d0 [snd_pcm] [ 170.116119] [<ffffffff810993d3>] ? check_preempt_wakeup+0xb3/0x210 [ 170.116124] [<ffffffffa062e63a>] ? snd_pcm_period_elapsed+0x6a/0xe0 [snd_pcm] [ 170.116127] [<ffffffffa0582f2b>] ? azx_interrupt+0x10b/0x1c0 [snd_hda_controller] [ 170.116131] [<ffffffff810c7f6d>] ? handle_irq_event_percpu+0x2d/0x1e0 [ 170.116134] [<ffffffff810c8159>] ? handle_irq_event+0x39/0x60 [ 170.116137] [<ffffffff810cafd1>] ? handle_edge_irq+0x91/0x150 [ 170.116140] [<ffffffff81017678>] ? handle_irq+0x18/0x30 [ 170.116143] [<ffffffff81016dfd>] ? do_IRQ+0x4d/0xf0 [ 170.116145] [<ffffffff81551fed>] ? common_interrupt+0x6d/0x6d [ 170.116146] <EOI> [<ffffffff8155126d>] ? system_call_fastpath+0x16/0x1b [ 171.815153] ALSA: PCM: [Q] Lost interrupts?: (stream=0, delta=161, new_hw_ptr=3207481, old_hw_ptr=3207320) [ 171.815160] CPU: 0 PID: 0 Comm: swapper/0 Not tainted 3.19.0-pf2+ #1 [ 171.815161] Hardware name: System manufacturer System Product Name/P8H61-M LX2, BIOS 0605 05/09/2013 [ 171.815163] 0000000000000000 0000000000000079 ffffffff8154b50a ffff8800948ab400 [ 171.815166] ffffffffa062e10f 0000000000014080 ffff880235e4b428 ffff880235e4b3c0 [ 171.815168] ffffffff810993d3 00ff88023fa14080 0000000000000000 00000001000277a3 [ 171.815170] Call Trace: [ 171.815172] <IRQ> [<ffffffff8154b50a>] ? dump_stack+0x4a/0x74 [ 171.815191] [<ffffffffa062e10f>] ? snd_pcm_update_hw_ptr0+0x40f/0x8d0 [snd_pcm] [ 171.815196] [<ffffffff810993d3>] ? check_preempt_wakeup+0xb3/0x210 [ 171.815199] [<ffffffff815508fc>] ? _raw_spin_unlock_irqrestore+0x1c/0x40 [ 171.815204] [<ffffffffa062e63a>] ? snd_pcm_period_elapsed+0x6a/0xe0 [snd_pcm] [ 171.815208] [<ffffffffa0582f2b>] ? azx_interrupt+0x10b/0x1c0 [snd_hda_controller] [ 171.815212] [<ffffffff810c7f6d>] ? handle_irq_event_percpu+0x2d/0x1e0 [ 171.815215] [<ffffffff810c8159>] ? handle_irq_event+0x39/0x60 [ 171.815217] [<ffffffff810cafd1>] ? handle_edge_irq+0x91/0x150 [ 171.815221] [<ffffffff81017678>] ? handle_irq+0x18/0x30 [ 171.815223] [<ffffffff81016dfd>] ? do_IRQ+0x4d/0xf0 [ 171.815226] [<ffffffff81551fed>] ? common_interrupt+0x6d/0x6d [ 171.815227] <EOI> [<ffffffff81427f99>] ? cpuidle_enter_state+0x59/0x1a0 [ 171.815232] [<ffffffff81427f89>] ? cpuidle_enter_state+0x49/0x1a0 [ 171.815235] [<ffffffff810a4599>] ? cpu_startup_entry+0x489/0x4f0 [ 171.815238] [<ffffffff818edf69>] ? start_kernel+0x47b/0x486 [ 171.815240] [<ffffffff818ed120>] ? early_idt_handlers+0x120/0x120 [ 171.815242] [<ffffffff818ed120>] ? early_idt_handlers+0x120/0x120 [ 171.815244] [<ffffffff818ed60d>] ? x86_64_start_kernel+0x150/0x15f
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]: [pulseaudio] alsa-util.c: access : MMAP_INTERLEAVED Apr 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 Apr 16 19:16:17 homecomp pulseaudio[6121]: [pulseaudio] alsa-util.c: tstamp_mode : ENABLE Apr 16 19:16:17 homecomp pulseaudio[6121]: [pulseaudio] alsa-util.c: period_step : 1 Apr 16 19:16:17 homecomp pulseaudio[6121]: [pulseaudio] alsa-util.c: avail_min : 1008 Apr 16 19:16:17 homecomp pulseaudio[6121]: [pulseaudio] alsa-util.c: period_event : 1 Apr 16 19:16:17 homecomp pulseaudio[6121]: [pulseaudio] alsa-util.c: start_threshold : -1 Apr 16 19:16:17 homecomp pulseaudio[6121]: [pulseaudio] alsa-util.c: stop_threshold : 9079256848778919936 Apr 16 19:16:17 homecomp pulseaudio[6121]: [pulseaudio] alsa-util.c: silence_threshold: 0 Apr 16 19:16:17 homecomp pulseaudio[6121]: [pulseaudio] alsa-util.c: silence_size : 0 Apr 16 19:16:17 homecomp pulseaudio[6121]: [pulseaudio] alsa-util.c: boundary : 9079256848778919936 Apr 16 19:16:17 homecomp pulseaudio[6121]: [pulseaudio] alsa-util.c: appl_ptr : 0 Apr 16 19:16:17 homecomp pulseaudio[6121]: [pulseaudio] alsa-util.c: hw_ptr : 0 The point is, while the configuration looks the same the latency is huge, it's exactly 168 ms and is just unbearable. That's what happens after some really bad PC slowdowns because of the workload and it happens for every app and there's no way to make it behave properly without restarting PA and everything else. So why PA doesn't work as dmix does? Why dmix has 168ms buffer and responds instantly like there's no perceptible latency? Why dmix never underruns (at least audibly) while PA does it pretty often on a range of chipsets? I would be pretty happy with 21 ms fixed latency that never underruns but I just can't setup PA to work like this. Please, Raymond, don't go into the details, like, this particular card isn't Intel HDA the period size in PA is slightly less (1008 vs 1024) and so on. I see it clearly, that's not important here. What's important is the fact that dmix does its job much better than PA in any configuration (negligible latency + no underruns) and I want to know why and how to make PA work like dmix in this regard.
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(substream->runtime, azx_get_position(chip, azx_dev)); }
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.
Use of freedesktop.org services, including Bugzilla, is subject to our Code of Conduct. How we collect and use information is described in our Privacy Policy.