overrun in second capture device after stopping first capture device

overrun in second capture device after stopping first capture device

[Tobias Schneider]

Dear ALSA Dev-Team,

while testing my driver, I figured out that under some circumstances 
there occur overruns when recording two streams:

first I startet a long capture at device 1:

-bash-3.2#
-bash-3.2# arecord -D hw:0,1 -d 180 -r 32000 -c 1 -t wav -f S16_LE 
arecord_049.wav
Recording WAVE 'arecord_049.wav' : Signed 16 bit Little Endian, Rate 
32000 Hz, Mono
overrun!!! (at least 121.536 ms long)
overrun!!! (at least 115.361 ms long)
overrun!!! (at least 190.883 ms long)
overrun!!! (at least 121.772 ms long)
overrun!!! (at least 119.487 ms long)

In another terminal, I started a second capture on the second device. 
Everytime
this capture is done, I got an overrun in the first capture (see above)

-bash-3.2#                                                                                                                                              
 
-bash-3.2# arecord -D hw:0,0 -d 15 -r 32000 -c 1 -t wav -f S16_LE 
arecord_047.wav
Recording WAVE 'arecord_047.wav' : Signed 16 bit Little Endian, Rate 
32000 Hz, Mono
-bash-3.2# arecord -D hw:0,0 -d 15 -r 32000 -c 1 -t wav -f S16_LE 
arecord_047.wav
Recording WAVE 'arecord_047.wav' : Signed 16 bit Little Endian, Rate 
32000 Hz, Mono
-bash-3.2# arecord -D hw:0,0 -d 15 -r 32000 -c 1 -t wav -f S16_LE 
arecord_047.wav
Recording WAVE 'arecord_047.wav' : Signed 16 bit Little Endian, Rate 
32000 Hz, Mono
-bash-3.2# arecord -D hw:0,0 -d 15 -r 32000 -c 1 -t wav -f S16_LE 
arecord_047.wav
Recording WAVE 'arecord_047.wav' : Signed 16 bit Little Endian, Rate 
32000 Hz, Mono
-bash-3.2# arecord -D hw:0,0 -d 15 -r 32000 -c 1 -t wav -f S16_LE 
arecord_047.wav
Recording WAVE 'arecord_047.wav' : Signed 16 bit Little Endian, Rate 
32000 Hz, Mono
-bash-3.2#

It seems, that the duration of the overrun relates to the capture time 
of the second capture, as it increases with bigger capture times. But if 
capture times are bigger than 25s, it seems there is no overrun...just 
some logs to clarify:

First Terminal:
-bash-3.2#
-bash-3.2# arecord -D hw:0,1 -d 180 -r 32000 -c 1 -t wav -f S16_LE 
arecord_049.wav
Recording WAVE 'arecord_049.wav' : Signed 16 bit Little Endian, Rate 
32000 Hz, Mono
overrun!!! (at least 99.074 ms long)

Second Terminal:
-bash-3.2#
-bash-3.2# arecord -D hw:0,0 -d 30 -r 32000 -c 1 -t wav -f S16_LE 
arecord_047.wav  
Recording WAVE 'arecord_047.wav' : Signed 16 bit Little Endian, Rate 
32000 Hz, Mono
-bash-3.2# arecord -D hw:0,0 -d 30 -r 32000 -c 1 -t wav -f S16_LE 
arecord_047.wav
Recording WAVE 'arecord_047.wav' : Signed 16 bit Little Endian, Rate 
32000 Hz, Mono
-bash-3.2# arecord -D hw:0,0 -d 30 -r 32000 -c 1 -t wav -f S16_LE 
arecord_047.wav
Recording WAVE 'arecord_047.wav' : Signed 16 bit Little Endian, Rate 
32000 Hz, Mono
-bash-3.2# arecord -D hw:0,0 -d 15 -r 32000 -c 1 -t wav -f S16_LE 
arecord_047.wav
Recording WAVE 'arecord_047.wav' : Signed 16 bit Little Endian, Rate 
32000 Hz, Mono
-bash-3.2#


First Terminal:
-bash-3.2# arecord -D hw:0,1 -d 180 -r 32000 -c 1 -t wav -f S16_LE 
arecord_049.wav
Recording WAVE 'arecord_049.wav' : Signed 16 bit Little Endian, Rate 
32000 Hz, Mono
overrun!!! (at least 193.656 ms long)


Second Terminal:
-bash-3.2# arecord -D hw:0,0 -d 25 -r 32000 -c 1 -t wav -f S16_LE 
arecord_047.wav
Recording WAVE 'arecord_047.wav' : Signed 16 bit Little Endian, Rate 
32000 Hz, Mono
-bash-3.2# arecord -D hw:0,0 -d 20 -r 32000 -c 1 -t wav -f S16_LE 
arecord_047.wav
Recording WAVE 'arecord_047.wav' : Signed 16 bit Little Endian, Rate 
32000 Hz, Mono
-bash-3.2#


So I am wondering why such an overrun occurs, can someone please give me 
some hints what my be the reason?

Thanks in Advance!
Tobias

Re: overrun in second capture device after stopping first capture device

[Tobias Schneider]

After searching a lot concerning underrun and xrun, I am still not satisfied
with the results, meaning I still have those problems. I figured out 
that increasing
buffer_size will reduce overruns. First I used 3*1284 byte, now with 
12*1284 byte
(each period_size is 1284 byte) the overruns occur only very very 
seldom...but a
buffer_size of 15408 Byte is very big, isn't it? I guess it also 
introduces more latency...


As it seems that there are a lot of new ALSA driver developers encountering
such a problem, I thought it might be a good idea to collect as many as 
possible
information related to this issue.

Please feel free to add / correct the following "FAQ". I will also keep 
track of
it and if it seems to satisfy most requests I would prefer adding a wiki 
page...


So what I have found about the underrun / overrun issue:

################################################################################
#01 What means underrun and overrun?
------------------------------------
Underrun means that you are playing audio and the device runs out of 
frames to
play. That means the hardware buffer is empty.
Overrun means you are recording audio, and the device runs out of buffer 
space
to put the audio.
 
(from 
http://www.mail-archive.com/alsa-user@lists.sourceforge.net/msg22803.html)

An "xrun" can be either a buffer underrun or a buffer overrun. In both 
cases an
audio app was either not fast enough to deliver data to the ALSA audio 
buffer or
not fast enough to process data from the ALSA audio buffer. Usually 
xruns are
audible as crackles or pops.

(from http://alsa.opensrc.org/index.php/Xruns)

Underrun means that the driver is consuming data more quickly than aplay
is able to provide it. This may mean that there's some system
performance problem or it may be due to your driver is consuming data
more quickly than it should and causing problems further up the stack.

(from http://thread.gmane.org/gmane.linux.alsa.devel/65035/focus=65147)

################################################################################
#02 Where is a buffer underrun or overrun detected?
---------------------------------------------------
XRUN will be reported in either of these functions

static inline int snd_pcm_update_hw_ptr_interrupt(struct
snd_pcm_substream *substream)

...
pos = substream->ops->pointer(substream);
    if (pos == SNDRV_PCM_POS_XRUN)
    xrun(substream);
        return -EPIPE;
...

or

static inline int snd_pcm_update_hw_ptr_post(struct snd_pcm_substream
*substream, struct snd_pcm_runtime *runtime)

...
if (avail >= runtime->stop_threshold) {
        if (substream->runtime->status->state == SNDRV_PCM_STATE_DRAINING)
            snd_pcm_drain_done(substream);
        else
            xrun(substream);
        return -EPIPE;
...

All these functions are in sound/core/pcm_lib.c

* PCM is automatically stopped in #SND_PCM_STATE_XRUN state when available
  frames is >= stop_threshold. If the stop_threshold is equal to 
boundary (also
  software parameter - sw_param) then automatic stop will be disabled
  (thus device will do the endless loop in the ring buffer).

STATES concerning XRUN:
  SND_PCM_STATE_XRUN
  SNDRV_PCM_STATE_XRUN
  SNDRV_PCM_POS_XRUN

Another description says, that an XRUN is detected if hw_ptr > appl_ptr.

################################################################################
#03 What means the xrun duration, how is it calculated?
--------------------------------------------------------------------------------
In aplay.c the duration of underrun or overrun is calculated via the 
trigger
tstamp and current time value:

    struct timeval now, diff, tstamp;
        gettimeofday(&now, 0);
        snd_pcm_status_get_trigger_tstamp(status, &tstamp);
        timersub(&now, &tstamp, &diff);
        fprintf(stderr, _("%s!!! (at least %.3f ms long)\n"),
            stream == SND_PCM_STREAM_PLAYBACK ? _("underrun") : 
_("overrun"),
            diff.tv_sec * 1000 + diff.tv_usec / 1000.0);

################################################################################
#04 What causes such a buffer underrun or overrun?
--------------------------------------------------------------------------------
There are various possibilities that can generate a xrun:

underrun:
  - The source is not able to deliver data as fast as it is required to
    - e.g. host system is busy, filesystem is busy, sheduling problem...
    - disk overload
  - the buffer DMA isn't properly updated or set up
  - the calculation of the current pointer doesn't match with the actual 
position
    - check return of pcm_pointer callback
  - the buffer and period setup is somehow weird
    - for example, it's set to very small period or buffer size, which can
      easily result in buffer underrun.

(from http://thread.gmane.org/gmane.linux.alsa.devel/55038
      http://thread.gmane.org/gmane.linux.alsa.devel/58921/focus=58922
      http://thread.gmane.org/gmane.linux.alsa.devel/58955/focus=58958)


Another hint:

Look at the order of measured (least) latency in both cases.
You case is almost 1 second delay while the previous one is less
than 1 ms.  Thus, in your case, it's either really a system latency
such as disk overload or that the buffer DMA isn't properly updated or
set up.

In the previous case, less than 1 ms latency, it implies that the
buffer and period setup is somehow weird.  For example, it's set to
the very small period or buffer size, which can easily result in
buffer underrun.  Check the hw_params constraints and snd_pcm_hardware
setting.


################################################################################
#05 What should be the return of pcm_pointer callback?
--------------------------------------------------------------------------------
The pointer callback is supposed to give the currently played position
offset in a ring buffer, and ranged from 0 to buffer_size-1.
When the first snd_pcm_period_elapsed() is called, it should be
(ideally) pointing at period_size, at the succeeding calls,
period_size*2, period_size*3, then 0 again (if buffer_size = 4*period_size).

Try to track the value returned from the pointer callback.

(from http://thread.gmane.org/gmane.linux.alsa.devel/65035/focus=65147)

The pointer callback reports the sane position as the current position;
not below the previous position and not above the next period boundary.

(from http://thread.gmane.org/gmane.linux.alsa.devel/61280/focus=62055)

pcm_pointer: This value and the timing of snd_pcm_period_elapsed() is 
the only
information the PCM core checks.

The ALSA PCM core just relies upon two things from the lowlevel driver:

1. The lowlevel driver calls snd_pcm_period_elapsed() at each time
   when the set-up period size has been processed by the hardware.
2. The pointer callback reports the sane position as the current
   position; not below the previous position and not above the next
   period boundary.

(from http://thread.gmane.org/gmane.linux.alsa.devel/61280/focus=62055)

################################################################################
#06 When is substream->dma_area used for playback or capture?
--------------------------------------------------------------------------------
 When is substream->dma_area used for capture or playback? (probably 
never, as
 snd_pcm_lib_malloc_pages() seems to imply that one should only use
 substream->runtime->dma_area)

It's used when the data is copied via copy_from/to_user(), or when the
buffer is mmapped.

Please note that you don't need this always. If you define copy and
silence callbacks, and if they don't handle any dma buffer on the cpu
side (e.g. buffers on a card), then you don't need this.
In such a case, mmap cannot be used.

Re: overrun in second capture device after stopping first capture device

[Tobias Schneider]

I am still searching what causes the problem, I now figured out that the 
underruns occur because appl_ptr = hw_ptr - so this is because appl_ptr 
is not moved forward. Are there any reasons for this?

<7>DEBUG: p1 hw_ptr=0x3cdd43 (3988803) appl_ptr=0x3cebbc (3992508) 
jiffie=21775142
<7>DEBUG: p1 hw_ptr=0x3ce028 (3989544) appl_ptr=0x3ceea1 (3993249) 
jiffie=21775165
<7>DEBUG: p1 hw_ptr=0x3ce30d (3990285) appl_ptr=0x3cf186 (3993990) 
jiffie=21775188
<7>DEBUG: p1 hw_ptr=0x3ce5f2 (3991026) appl_ptr=0x3cf46b (3994731) 
jiffie=21775212
<7>DEBUG: p1 hw_ptr=0x3ce8d7 (3991767) appl_ptr=0x3cf750 (3995472) 
jiffie=21775235
<7>DEBUG: p1 hw_ptr=0x3cebbc (3992508) appl_ptr=0x3cf750 (3995472) 
jiffie=21775258
<7>DEBUG: p1 hw_ptr=0x3ceea1 (3993249) appl_ptr=0x3cf750 (3995472) 
jiffie=21775281
<7>DEBUG: p1 hw_ptr=0x3cf186 (3993990) appl_ptr=0x3cf750 (3995472) 
jiffie=21775304
<7>DEBUG: p1 hw_ptr=0x3cf46b (3994731) appl_ptr=0x3cf750 (3995472) 
jiffie=21775328
<7>DEBUG: p1 hw_ptr=0x3cf750 (3995472) appl_ptr=0x3cf750 (3995472) 
jiffie=21775351
<3>ERROR: p1 XRUN B! avail = 4446  stop_threshold = 4446 jiffie_diff=23
<7>DEBUG: playback trigger (1): cmd=stop
<7>DEBUG: trigger stop jiffies=21775351
<7>DEBUG: trigger stop jiffies difference =124742
<7>DEBUG: - pcm_timer_stop
<7>DEBUG: pcm prepare

I will go on searching for the reason, but I am thankful for any hint...