Test latency.c

From AlsaProject
Jump to: navigation, search

Contents

test latency.c

Within alsa-lib, there is a utility, test/latency.c (history), which performs a full-duplex test, where recorded (captured) data is played back.

From alsa-lib/test/latency.c:

 *  Latency test program
 *
 *  This small demo program can be used for measuring latency between
 *  capture and playback. This latency is measured from driver (diff when
 *  playback and capture was started). Scheduler is set to SCHED_RR.


Building

The name of the executable has to be passed explicitly to the make command - via Re: problem ragarding execution of Latency.c (alsa-devel):

cd alsa-lib/test
make latency


Options

$ ./latency -h
Usage: latency [OPTION]... [FILE]...
-h,--help      help
-P,--pdevice   playback device
-C,--cdevice   capture device
-m,--min       minimum latency in frames
-M,--max       maximum latency in frames
-F,--frames    frames to transfer
-f,--format    sample format
-c,--channels  channels
-r,--rate      rate
-B,--buffer    buffer size in frames
-E,--period    period size in frames
-s,--seconds   duration of test in seconds
-b,--block     block mode
-p,--poll      use poll (wait for event - reduces CPU usage)
-e,--effect    apply an effect (bandpass filter sweep)
Recognized sample formats are: S8 U8 S16_LE S16_BE U16_LE U16_BE S24_LE S24_BE U24_LE U24_BE S32_LE S32_BE U32_LE U32_BE FLOAT_LE FLOAT_BE FLOAT64_LE FLOAT64_BE IEC958_SUBFRAME_LE IEC958_SUBFRAME_BE MU_LAW A_LAW IMA_ADPCM MPEG GSM SPECIAL S24_3LE S24_3BE U24_3LE U24_3BE S20_3LE S20_3BE U20_3LE U20_3BE S18_3LE S18_3BE U18_3LE

Tip #1 (usable latency with large periods, non-blocking mode, good CPU usage,
        superb xrun prevention):
  latency -m 8192 -M 8192 -t 1 -p
Tip #2 (superb latency, non-blocking mode, but heavy CPU usage):
  latency -m 128 -M 128


Notes:

  • The option -F,--frames seems not to be handled anywhere in the code, and as such has no effect.
  • The "Tip #1" refers to an option -t which doesn't exist - however, it is likely a typo for the option -s for duration in seconds
  • The option -s for duration in seconds is an integer, and the lowest it can be set is 1 second; default if not specified is 30 seconds
  • Before 2012-08-08, there is a bug where the short options -B and -E are not recognized ("invalid option") - but the long options --buffer and --period still work even then.


Usage

When called, the test/latency.c program will attemp to set period/buffer sizes based on the latency entered, starting from -m,--min option (or the default minimum latency = 64 if not specified). If the run succeeds without errors with that setting, the program exits; otherwise, the latency is increased, and the run repeated - if the run is succesful here, then program exits, else the process continues until the -M,--max latency is reached.

Example of successful run on Linux kernel 2.6.38 / ALSA 1.0.24.2 with HDA Intel onboard PCI soundcard:

$ aplay -l
**** List of PLAYBACK Hardware Devices ****
card 0: Intel [HDA Intel], device 0: ALC269 Analog [ALC269 Analog]
  Subdevices: 1/1
  Subdevice #0: subdevice #0

$ alsa-lib/test/latency -P hw:0,0 -C hw:0,0 -r 44100 -m 128 -M 128 -p -s 1
!!!Scheduler set to Round Robin with priority 99 FAILED!!!
Playback device is hw:0,0
Capture device is hw:0,0
Parameters are 44100Hz, S16_LE, 2 channels, non-blocking mode
Poll mode: yes
Loop limit is 44100 frames, minimum latency = 128, maximum latency = 128
Hardware PCM card 0 'HDA Intel' 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  : 128
  period_size  : 64
  period_time  : 1451
  tstamp_mode  : NONE
  period_step  : 1
  avail_min    : 64
  period_event : 0
  start_threshold  : 2147483647
  stop_threshold   : 128
  silence_threshold: 0
  silence_size : 0
  boundary     : 1073741824
  appl_ptr     : 0
  hw_ptr       : 0
Hardware PCM card 0 'HDA Intel' device 0 subdevice 0
Its setup is:
  stream       : CAPTURE
  access       : RW_INTERLEAVED
  format       : S16_LE
  subformat    : STD
  channels     : 2
  rate         : 44100
  exact rate   : 44100 (44100/1)
  msbits       : 16
  buffer_size  : 128
  period_size  : 64
  period_time  : 1451
  tstamp_mode  : NONE
  period_step  : 1
  avail_min    : 64
  period_event : 0
  start_threshold  : 2147483647
  stop_threshold   : 128
  silence_threshold: 0
  silence_size : 0
  boundary     : 1073741824
  appl_ptr     : 0
  hw_ptr       : 0
Trying latency 128 frames, 2902.494us, 2.902494ms (344.5312Hz)
Success
Playback:
*** frames = 44288 ***
  state       : RUNNING
  trigger_time: 84416.108859821
  tstamp      : 84417.110319083
  delay       : 80
  avail       : 48
  avail_max   : 120
Capture:
*** frames = 44160 ***
  state       : RUNNING
  trigger_time: 84416.108859821
  tstamp      : 84417.110439490
  delay       : 9
  avail       : 9
  avail_max   : 65
Maximum read: 64 frames
Maximum read latency: 1451.247us, 1.451247ms (689.0625Hz)
Hardware sync
Playback time = 84416.108859, Record time = 84416.108859, diff = 0

The message "Scheduler set to Round Robin with priority 99 FAILED" can be avoided by running the program with sudo (administrative privileges):

$ sudo alsa-lib/test/latency -P hw:0,0 -C hw:0,0 -r 44100 -m 128 -M 128 -p -s 1
[sudo] password for user:
Scheduler set to Round Robin with priority 99...
...

The program can also fail, if the streams experience an XRUN; in that case, if -m is set to be equal to -M, the program will immediately exit:

$ alsa-lib/test/latency -P hw:0,0 -C hw:0,0 -r 44100 -m 128 -M 128 -p -s 1
!!!Scheduler set to Round Robin with priority 99 FAILED!!!
Playback device is hw:0,0
Capture device is hw:0,0
Parameters are 44100Hz, S16_LE, 2 channels, non-blocking mode
Poll mode: yes
Loop limit is 44100 frames, minimum latency = 128, maximum latency = 128
Hardware PCM card 0 'HDA Intel' 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  : 128
  period_size  : 64
  period_time  : 1451
  tstamp_mode  : NONE
  period_step  : 1
  avail_min    : 64
  period_event : 0
  start_threshold  : 2147483647
  stop_threshold   : 128
  silence_threshold: 0
  silence_size : 0
  boundary     : 1073741824
  appl_ptr     : 0
  hw_ptr       : 0
Hardware PCM card 0 'HDA Intel' device 0 subdevice 0
Its setup is:
  stream       : CAPTURE
  access       : RW_INTERLEAVED
  format       : S16_LE
  subformat    : STD
  channels     : 2
  rate         : 44100
  exact rate   : 44100 (44100/1)
  msbits       : 16
  buffer_size  : 128
  period_size  : 64
  period_time  : 1451
  tstamp_mode  : NONE
  period_step  : 1
  avail_min    : 64
  period_event : 0
  start_threshold  : 2147483647
  stop_threshold   : 128
  silence_threshold: 0
  silence_size : 0
  boundary     : 1073741824
  appl_ptr     : 0
  hw_ptr       : 0
Trying latency 128 frames, 2902.494us, 2.902494ms (344.5312Hz)
Failure
Playback:
*** frames = 38464 ***
  state       : XRUN
  trigger_time: 479.798093354
  tstamp      : 479.798185056
  delay       : 0
  avail       : 128
  avail_max   : 128
Capture:
*** frames = 38400 ***
  state       : XRUN
  trigger_time: 479.798093354
  tstamp      : 479.798361196
  delay       : 0
  avail       : 9
  avail_max   : 73
Maximum read: 64 frames
Maximum read latency: 1451.247us, 1.451247ms (689.0625Hz)
Hardware sync


Quick overview

In brief, the latency.c program:

  • Parses the command line parameters/options, and sets the playback and capture stream properties according to them
  • Starts a loop where (among other things) it:
    • shows the current latency value, using the showlatency() function - which ultimately prints the "Trying latency %li frames ..." line
      • Note: the showlatency(size_t latency) function multiplies the latency input argument by two (latency *= 2;); so if the printout says "Trying latency 128 frames ...", that means that latency parameter is actually 64
    • calls snd_pcm_link on the capture and playback stream file descriptors, to have them "start/stop/prepare in sync"
    • calls snd_pcm_format_set_silence, and then
    • calls writebuf(phandle, buffer, latency ...) twice
      • Note: since the value of the variable latency is twice smaller than what the printout "Trying latency %li frames ..." says - calling writebuf() twice, means that we ultimately achieve the demanded latency, as shown on the printout.
    • starts yet another while loop, where:
      • snd_pcm_wait is called, if polling has been specified in the command line arguments;
      • r = readbuf(chandle, buffer, latency, ...) is called on the capture stream
      • writebuf(phandle, buffer, r, ...) is called on the playback stream

See the source code for details of the readbuf() and writebuf() functions - which may involve loops of their own, but ultimately call snd_pcm_readi and snd_pcm_writei, respectively.

Mailing list notes

latency.c: some feature requests (alsa-devel) (2004-11-28)

> It looks like the playback runs 64 frames ahead of the capture.  Do you
> think this would be a problem from the application's perspective?
>

That's correct - it's the latency.

-----

>>>>> I also need the capture device interleaved and the playback device
>>>>> noninterleaved.  latency.c does not support this at all, it just assumes
>>>>> that all hardware supports interleaved format.
>>>> Use default device (-D default and -P default) which automatically
>>>> uses available parameters.
>>>
>>> This will not work because I need to use hw:0,3 for playback and hw:0,2
>>> for capture.
>>
>> -P plughw:0,3 -C plughw:0,2

-----

>
> [...] One other thing I noticed is that latency.c doesn't mmap.
> This would cause higher latencies compared to testing with JACK,
> correct?

Yes, it's good point. Perhaps, the snd_pcm_mmap_readi/writei functions
should be used to optimize copying.


latency.c and delay related questions (alsa-devel) (2006-06-20)

> The current delay with "latency" is equal to a minimum (that depends
> on the sound card) plus *two* times the period time.  [...]

Yes, it's correct. Basically, you cannot avoid double buffering, so the
total latency is:

1) one capture period
2) one playback period (actually being played)
3) moved captured period to playback buffer (not counted)

So the latency should be 2 * period plus a hw latency as you noted.
Everything is correct. Of course, you may get better latencies if you run
"busy loop" on not-loaded system and immediately put captured data to
playback stream, but it's not a correct behaviour in *nix.

> * why is snd_pcm_link() mandatory? (no sound otherwise)

It links playback and capture streams so only one start() is called. On
hardware which supports hardware syncing, the DMA operation is started at
same time for both stream.

> * why two buffers of silence and not just one?

You must wait one period to get data from the capture direction and then
you have exactly one period time to put these data to the playback. As I
said, you can get better results with busy-loop but it's bad
implementation (but if you have a spare dedicated machine without other
tasks, it might be an option).

-----

> [...] The linking of capture and playback devices
> explains everything; if I remove linking and use snd_pcm_start() on
> the playback device I get the expected behaviour.
>
> Here is a little drawing (requires fixed font) to illustrate what you
> have said and what I have understood (useless for you but some people
> like me might find it useful).
>
> When capture and playback devices are linked, the following happens:
>
>          +-------------------------
> Capture  | C0 | C1 | C2 | C3 | ...
>          +-------------------------
>
>          +-------------------------
> Playback | -- | -- | C0 | C1 | ...
>          +-------------------------
>
> Capture and playback start simultaneously and so playback device needs
> something to play. When the first capture is finished, another is
> started. We would like to play the captured audio, but another
> playback has already started. Only after the latter is finished can
> the captured audio be played.
>
> This explains why the playback device needs two buffers of silence.
>
> The total delay is hw_delay + 2 * period
>

Exactly. Well explained.

> When the devices are not linked, we can start the playback device
> after the first buffer has been captured:
>
>          +-------------------------
> Capture  | C0 | C1 | C2 | C3 | ...
>          +-------------------------
>
>                  +-----------------
> Playback         | C0 | C1 | C2 | .
>                  +-----------------
>
> Starting the playback device and copying data takes some time, so the
> total delay becomes hw_delay + 1 * period + start_delay + copy_delay.
> For large periods, with period > start_delay + copy_delay, this can
> lead to a lower latency, but who would use large periods for low
> latency?
>

Yes, this buffering schema is also possible, but note that the time window
for the data copy must satisfy the system scheduler requirements and
capabilities to get continous playback. In the "stream linked" case this
time window is exactly one period time.


Meaning of --buffer and --period

Given the specific operation of the program outlined above, note that:

  • The latency parameter, derived from -m/--min and -M/--max parameters, ultimately translates to the PCM buffer_size
  • Specifying --buffer ultimately translates to the PCM period_size, and PCM buffer_size becomes 2x that - so we can consider it as a latency specification alternative to -m/--min and -M/--max
  • Specifying --period does override the PCM period_size, leaving the PCM buffer_size untouched; however, the program will typically exit with an error, if the period_size happens to be not equal to buffer_size/2 and smaller than buffer_size/2 (for values >= buffer_size/2, the engine automatically limits period_size to buffer_size/2)

The easiest way to observe that is to patch/add the following printf statements to the setparams_bufsize function:

int setparams_bufsize(...)
{
	int err;
	snd_pcm_uframes_t periodsize;

	snd_pcm_hw_params_copy(params, tparams);
	periodsize = bufsize * 2;
	printf(" spbf: in bufsize:%li ; periodsize %li for %s\n", bufsize, periodsize, id); //added
	err = snd_pcm_hw_params_set_buffer_size_near(handle, params, &periodsize);
	if (err < 0) {
		printf("Unable to set buffer size %li for %s: %s\n", bufsize * 2, id, snd_strerror(err));
		return err;
	}
	printf("     ; set_buffer_size_near: %li for %s\n", periodsize, id);                //added
	if (period_size > 0)
		periodsize = period_size;
	else
		periodsize /= 2;
	printf("     ; now periodsize %li for %s\n", periodsize, id);                       //added
	err = snd_pcm_hw_params_set_period_size_near(handle, params, &periodsize, 0);
	if (err < 0) {
		printf("Unable to set period size %li for %s: %s\n", periodsize, id, snd_strerror(err));
		return err;
	}
	printf("     ; set_period_size_near: %li for %s\n", periodsize, id);                //added
	return 0;
}


With this change, we can now observe the buffer/period size calculations:

$ ./latency -P hw:0,0 -C hw:0,0 -r 44100 -m 64 -M 64 -p -s 1 | grep 'size\|Trying\|limit\|state\|stream\|Max'
Loop limit is 44100 frames, minimum latency = 64, maximum latency = 64
 spbf: in bufsize:32 ; periodsize 64 for playback
     ; set_buffer_size_near: 64 for playback
     ; now periodsize 32 for playback
     ; set_period_size_near: 32 for playback
 spbf: in bufsize:32 ; periodsize 64 for capture
     ; set_buffer_size_near: 64 for capture
     ; now periodsize 32 for capture
     ; set_period_size_near: 32 for capture
  stream       : PLAYBACK
  buffer_size  : 64
  period_size  : 32
  silence_size : 0
  stream       : CAPTURE
  buffer_size  : 64
  period_size  : 32
  silence_size : 0
Trying latency 64 frames, 1451.247us, 1.451247ms (689.0625Hz)
  state       : XRUN
  state       : XRUN
Maximum read: 32 frames
Maximum read latency: 725.624us, 0.725624ms (1378.1250Hz)

$ ./latency -P hw:0,0 -C hw:0,0 -r 44100 -m 128 -M 128 -p -s 1 | grep 'size\|Trying\|limit\|state\|stream\|Max'
Loop limit is 44100 frames, minimum latency = 128, maximum latency = 128
 spbf: in bufsize:64 ; periodsize 128 for playback
     ; set_buffer_size_near: 128 for playback
     ; now periodsize 64 for playback
     ; set_period_size_near: 64 for playback
 spbf: in bufsize:64 ; periodsize 128 for capture
     ; set_buffer_size_near: 128 for capture
     ; now periodsize 64 for capture
     ; set_period_size_near: 64 for capture
  stream       : PLAYBACK
  buffer_size  : 128
  period_size  : 64
  silence_size : 0
  stream       : CAPTURE
  buffer_size  : 128
  period_size  : 64
  silence_size : 0
Trying latency 128 frames, 2902.494us, 2.902494ms (344.5312Hz)
  state       : XRUN
  state       : XRUN
Maximum read: 64 frames
Maximum read latency: 1451.247us, 1.451247ms (689.0625Hz)

$ ./latency -P hw:0,0 -C hw:0,0 -r 44100 -m 256 -M 256 -p -s 1 | grep 'size\|Trying\|limit\|state\|stream\|Max'
Loop limit is 44100 frames, minimum latency = 256, maximum latency = 256
 spbf: in bufsize:128 ; periodsize 256 for playback
     ; set_buffer_size_near: 256 for playback
     ; now periodsize 128 for playback
     ; set_period_size_near: 128 for playback
 spbf: in bufsize:128 ; periodsize 256 for capture
     ; set_buffer_size_near: 256 for capture
     ; now periodsize 128 for capture
     ; set_period_size_near: 128 for capture
  stream       : PLAYBACK
  buffer_size  : 256
  period_size  : 128
  silence_size : 0
  stream       : CAPTURE
  buffer_size  : 256
  period_size  : 128
  silence_size : 0
Trying latency 256 frames, 5804.989us, 5.804989ms (172.2656Hz)
  state       : RUNNING
  state       : RUNNING
Maximum read: 128 frames
Maximum read latency: 2902.494us, 2.902494ms (344.5312Hz)

# so, we have:
# -m 64 -M 64   -> buffer_size  : 64   -> Trying latency 64 frames
# -m 128 -M 128 -> buffer_size  : 128  -> Trying latency 128 frames
# -m 256 -M 256 -> buffer_size  : 256  -> Trying latency 256 frames


$ ./latency -P hw:0,0 -C hw:0,0 -r 44100 --buffer 128 -p -s 1 | grep 'size\|Trying\|limit\|state\|stream\|Max'
Loop limit is 44100 frames, minimum latency = 64, maximum latency = 4096
 spbf: in bufsize:128 ; periodsize 256 for playback
     ; set_buffer_size_near: 256 for playback
     ; now periodsize 128 for playback
     ; set_period_size_near: 128 for playback
 spbf: in bufsize:128 ; periodsize 256 for capture
     ; set_buffer_size_near: 256 for capture
     ; now periodsize 128 for capture
     ; set_period_size_near: 128 for capture
  stream       : PLAYBACK
  buffer_size  : 256
  period_size  : 128
  silence_size : 0
  stream       : CAPTURE
  buffer_size  : 256
  period_size  : 128
  silence_size : 0
Trying latency 256 frames, 5804.989us, 5.804989ms (172.2656Hz)
  state       : RUNNING
  state       : RUNNING
Maximum read: 128 frames
Maximum read latency: 2902.494us, 2.902494ms (344.5312Hz)

$ ./latency -P hw:0,0 -C hw:0,0 -r 44100 --buffer 256 -p -s 1 | grep 'size\|Trying\|limit\|state\|stream\|Max'
Loop limit is 44100 frames, minimum latency = 64, maximum latency = 4096
 spbf: in bufsize:256 ; periodsize 512 for playback
     ; set_buffer_size_near: 512 for playback
     ; now periodsize 256 for playback
     ; set_period_size_near: 256 for playback
 spbf: in bufsize:256 ; periodsize 512 for capture
     ; set_buffer_size_near: 512 for capture
     ; now periodsize 256 for capture
     ; set_period_size_near: 256 for capture
  stream       : PLAYBACK
  buffer_size  : 512
  period_size  : 256
  silence_size : 0
  stream       : CAPTURE
  buffer_size  : 512
  period_size  : 256
  silence_size : 0
Trying latency 512 frames, 11609.977us, 11.609977ms (86.1328Hz)
  state       : RUNNING
  state       : RUNNING
Maximum read: 256 frames
Maximum read latency: 5804.989us, 5.804989ms (172.2656Hz)

# so, we have:
# --buffer 128   -> buffer_size  : 256   -> Trying latency 256 frames
# --buffer 256   -> buffer_size  : 512   -> Trying latency 512 frames


$ ./latency -P hw:0,0 -C hw:0,0 -r 44100 -m 128 -M 128 --period 64 -p -s 1 | grep 'size\|Trying\|limit\|state\|stream\|Max\|support'
Loop limit is 44100 frames, minimum latency = 128, maximum latency = 128
 spbf: in bufsize:64 ; periodsize 128 for playback
     ; set_buffer_size_near: 128 for playback
     ; now periodsize 64 for playback
     ; set_period_size_near: 64 for playback
 spbf: in bufsize:64 ; periodsize 128 for capture
     ; set_buffer_size_near: 128 for capture
     ; now periodsize 64 for capture
     ; set_period_size_near: 64 for capture
  stream       : PLAYBACK
  buffer_size  : 128
  period_size  : 64
  silence_size : 0
  stream       : CAPTURE
  buffer_size  : 128
  period_size  : 64
  silence_size : 0
Trying latency 128 frames, 2902.494us, 2.902494ms (344.5312Hz)
  state       : XRUN
  state       : XRUN
Maximum read: 64 frames
Maximum read latency: 1451.247us, 1.451247ms (689.0625Hz)

$ ./latency -P hw:0,0 -C hw:0,0 -r 44100 -m 128 -M 128 --period 128 -p -s 1 | grep 'size\|Trying\|limit\|state\|stream\|Max\|support'
Loop limit is 44100 frames, minimum latency = 128, maximum latency = 128
 spbf: in bufsize:64 ; periodsize 128 for playback
     ; set_buffer_size_near: 128 for playback
     ; now periodsize 128 for playback
     ; set_period_size_near: 64 for playback
 spbf: in bufsize:64 ; periodsize 128 for capture
     ; set_buffer_size_near: 128 for capture
     ; now periodsize 128 for capture
     ; set_period_size_near: 64 for capture
  stream       : PLAYBACK
  buffer_size  : 128
  period_size  : 64
  silence_size : 0
  stream       : CAPTURE
  buffer_size  : 128
  period_size  : 64
  silence_size : 0
Trying latency 128 frames, 2902.494us, 2.902494ms (344.5312Hz)
  state       : XRUN
  state       : XRUN
Maximum read: 64 frames
Maximum read latency: 1451.247us, 1.451247ms (689.0625Hz)

$ ./latency -P hw:0,0 -C hw:0,0 -r 44100 -m 128 -M 128 --period 32 -p -s 1 | grep 'size\|Trying\|limit\|state\|stream\|Max\|support'
Loop limit is 44100 frames, minimum latency = 128, maximum latency = 128
 spbf: in bufsize:64 ; periodsize 128 for playback
     ; set_buffer_size_near: 128 for playback
     ; now periodsize 32 for playback
     ; set_period_size_near: 32 for playback
 spbf: in bufsize:64 ; periodsize 128 for capture
     ; set_buffer_size_near: 128 for capture
     ; now periodsize 32 for capture
     ; set_period_size_near: 32 for capture
playback device does not support 2 periods per buffer

# so, we have - for buffer_size/latency=128 (spec'd by -m 128 -M 128):
# --period 64   -> period_size  : 64    -> Trying latency 128 frames
# --period 128  -> period_size  : 64    -> Trying latency 128 frames
# --period 32   -> period_size  : 32    -> (error buffer_size != 2*period_size)

Note that the "device does not support 2 periods per buffer" message comes from a revision to latency.c from 2011-04-20; earlier versions will exit, but not print a message.


Algorithm locking

Note that it is also possible to "lock" the program, especially if automatic latency increase is allowed by specifying different -m/--min and -M/--max options, and the very first run fails with an XRUN (which can happen often for small PCM period/buffer sizes).

For instance, under Linux kernel 2.6.38 / ALSA 1.0.24.2, HDA Intel can typically lock with -m 64 -M 128 or -m 64 -M 128:

$ ./latency -P hw:0,0 -C hw:0,0 -r 44100 -m 64 -M 128 -p -s 1
!!!Scheduler set to Round Robin with priority 99 FAILED!!!
Playback device is hw:0,0
Capture device is hw:0,0
Parameters are 44100Hz, S16_LE, 2 channels, non-blocking mode
Poll mode: yes
Loop limit is 44100 frames, minimum latency = 64, maximum latency = 128
 spbf: in bufsize:32 ; periodsize 64 for playback
     ; set_buffer_size_near: 64 for playback
     ; now periodsize 32 for playback
     ; set_period_size_near: 32 for playback
 spbf: in bufsize:32 ; periodsize 64 for capture
     ; set_buffer_size_near: 64 for capture
     ; now periodsize 32 for capture
     ; set_period_size_near: 32 for capture
Hardware PCM card 0 'HDA Intel' 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  : 64
  period_size  : 32
  period_time  : 725
  tstamp_mode  : NONE
  period_step  : 1
  avail_min    : 32
  period_event : 0
  start_threshold  : 2147483647
  stop_threshold   : 64
  silence_threshold: 0
  silence_size : 0
  boundary     : 1073741824
  appl_ptr     : 0
  hw_ptr       : 0
Hardware PCM card 0 'HDA Intel' device 0 subdevice 0
Its setup is:
  stream       : CAPTURE
  access       : RW_INTERLEAVED
  format       : S16_LE
  subformat    : STD
  channels     : 2
  rate         : 44100
  exact rate   : 44100 (44100/1)
  msbits       : 16
  buffer_size  : 64
  period_size  : 32
  period_time  : 725
  tstamp_mode  : NONE
  period_step  : 1
  avail_min    : 32
  period_event : 0
  start_threshold  : 2147483647
  stop_threshold   : 64
  silence_threshold: 0
  silence_size : 0
  boundary     : 1073741824
  appl_ptr     : 0
  hw_ptr       : 0
Trying latency 64 frames, 1451.247us, 1.451247ms (689.0625Hz)
Failure
Playback:
*** frames = 64 ***
  state       : XRUN
  trigger_time: 7448.736132319
  tstamp      : 7448.736189100
  delay       : 0
  avail       : 81
  avail_max   : 81
Capture:
*** frames = 32 ***
  state       : XRUN
  trigger_time: 7448.736132319
  tstamp      : 7448.736301335
  delay       : 0
  avail       : 1
  avail_max   : 33
Maximum read: 32 frames
Maximum read latency: 725.624us, 0.725624ms (1378.1250Hz)
Hardware sync
 spbf: in bufsize:36 ; periodsize 72 for playback
     ; set_buffer_size_near: 64 for playback
     ; now periodsize 32 for playback
     ; set_period_size_near: 32 for playback
 spbf: in bufsize:36 ; periodsize 72 for capture
     ; set_buffer_size_near: 64 for capture
     ; now periodsize 32 for capture
     ; set_period_size_near: 32 for capture
Hardware PCM card 0 'HDA Intel' 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  : 64
  period_size  : 32
  period_time  : 725
  tstamp_mode  : NONE
  period_step  : 1
  avail_min    : 32
  period_event : 0
  start_threshold  : 2147483647
  stop_threshold   : 64
  silence_threshold: 0
  silence_size : 0
  boundary     : 1073741824
  appl_ptr     : 0
  hw_ptr       : 0
Hardware PCM card 0 'HDA Intel' device 0 subdevice 0
Its setup is:
  stream       : CAPTURE
  access       : RW_INTERLEAVED
  format       : S16_LE
  subformat    : STD
  channels     : 2
  rate         : 44100
  exact rate   : 44100 (44100/1)
  msbits       : 16
  buffer_size  : 64
  period_size  : 32
  period_time  : 725
  tstamp_mode  : NONE
  period_step  : 1
  avail_min    : 32
  period_event : 0
  start_threshold  : 2147483647
  stop_threshold   : 64
  silence_threshold: 0
  silence_size : 0
  boundary     : 1073741824
  appl_ptr     : 0
  hw_ptr       : 0
Trying latency 72 frames, 1632.653us, 1.632653ms (612.5000Hz)
^C


So, first the application is "Trying latency 64 frames", experiences an XRUN there, and then repeats the process, this time "Trying latency 72 frames". At this point, the application locks, and Ctrl-C needs to issued in the terminal to stop the application. Note that - in both cases - the engine decides on PCM buffer_size: 64, and period_size: 32 frames; regardless of what is specified as input latency.

Note that if we piped the output to grep also in the above example, similarly to previous examples - it is very likely that we would not observe the "Trying latency 72 frames ..." line.

A quick debug would be to first run the program through strace:

$ strace ./latency -P hw:0,0 -C hw:0,0 -r 44100 -m 64 -M 128 -p -s 1
...
ioctl(4, 0x400c4150, 0xbfc7f6c8)        = -1 EAGAIN (Resource temporarily unavailable)
ioctl(4, 0x400c4150, 0xbfc7f6c8)        = -1 EAGAIN (Resource temporarily unavailable)
ioctl(4, 0x400c4150, 0xbfc7f6c8)        = -1 EAGAIN (Resource temporarily unavailable)
ioctl(4, 0x400c4150, 0xbfc7f6c8)        = -1 EAGAIN (Resource temporarily unavailable)
^C--- SIGINT (Interrupt) @ 0 (0) ---

... which tells us that the program gets stuck on an ioctl system call, repeatedly trying to complete it (and again, Ctrl-C needs to issued in the terminal to stop the application).

To see more precisely where this problem occurs, we can run the program in the gdb debugger; wait for it to lock - and when it does, we can issue Ctrl-C to break into the program, and then issue bt to obtain a backtrace.

It should be noted here that alsa-lib/test/latency is actually a shell script, which loads the libraries built from the specific alsa-lib/ source folder; however, for gdb, we need the actual executable, which is typically in alsa-lib/test/.libs/lt-latency or alsa-lib/test/.libs/latency (not sure why this name can vary; the lt- prefix is likely due to ltmain.sh (GNU libtool)).

So, the gdb session would look like this:

$ gdb --args alsa-lib/test/.libs/latency -P hw:0,0 -C hw:0,0 -r 44100 -m 64 -M 128 -p -s 1
GNU gdb (GDB) 7.3.50.20110806-cvs
...
Reading symbols from /path/to/alsa-lib/test/.libs/latency...done.
(gdb) r
...
...
Trying latency 72 frames, 1632.653us, 1.632653ms (612.5000Hz)
^C
Program received signal SIGINT, Interrupt.
0x0012e416 in __kernel_vsyscall ()
(gdb) bt
#0  0x0012e416 in __kernel_vsyscall ()
#1  0x002c97c9 in ioctl () from /lib/i386-linux-gnu/libc.so.6
#2  0x00182890 in ?? () from /usr/lib/libasound.so.2
#3  0x00171ac4 in snd_pcm_writei () from /usr/lib/libasound.so.2
#4  0x0804a23b in writebuf (handle=0x8056ed8, buf=0x804e0b8 "", len=8, frames=0xbffff1bc) at latency.c:383
#5  0x0804ab8d in main (argc=14, argv=0xbffff294) at latency.c:639

... which confirms that the failing ioctl is due to a snd_pcm_writei call.

Custom Search
Personal tools
Namespaces

Variants
Actions
Navigation
wiki
Toolbox