Test latency.c - Revision history

Sdaau: /* Quick overview */ - added clarification about "Trying latency ..." line

2013-09-18T05:45:00Z

Quick overview: - added clarification about "Trying latency ..." line

← Older revision		Revision as of 05:45, 18 September 2013
Line 253:		Line 253:
	* Starts a loop where (among other things) it:		* Starts a loop where (among other things) it:
	** shows the current latency value, using the <code>showlatency()</code> function - which ultimately prints the "<i>Trying latency %li frames ...</i>" line		** shows the current latency value, using the <code>showlatency()</code> function - which ultimately prints the "<i>Trying latency %li frames ...</i>" line
			*** <small><i>Note:</i> the <code>showlatency(size_t latency)</code> function multiplies the <code>latency</code> input argument by two (<code>latency *= 2;</code>); so if the printout says "<i>Trying latency 128 frames ...</i>", that means that <code>latency</code> parameter is actually 64</small>
	** calls [http://www.alsa-project.org/alsa-doc/alsa-lib/group___p_c_m.html#gac6c33091b049985baa6466e8fe93917e snd_pcm_link] on the capture and playback stream file descriptors, to have them "<i>start/stop/prepare in sync</i>"		** calls [http://www.alsa-project.org/alsa-doc/alsa-lib/group___p_c_m.html#gac6c33091b049985baa6466e8fe93917e snd_pcm_link] on the capture and playback stream file descriptors, to have them "<i>start/stop/prepare in sync</i>"
	** calls <code>snd_pcm_format_set_silence</code>, and then		** calls <code>snd_pcm_format_set_silence</code>, and then
	** calls <code>writebuf(phandle, buffer, latency ...)</code> '''''twice'''''		** calls <code>writebuf(phandle, buffer, latency ...)</code> '''''twice'''''
			*** <small><i>Note:</i> since the value of the variable <code>latency</code> is twice smaller than what the printout "<i>Trying latency %li frames ...</i>" says - calling <code>writebuf()</code> twice, means that we ultimately achieve the demanded latency, as shown on the printout.</small>
	** starts yet another <code>while</code> loop, where:		** starts yet another <code>while</code> loop, where:
	*** [http://www.alsa-project.org/alsa-doc/alsa-lib/group___p_c_m.html#gad4d53d58b996a7cd9a5cbf1710b90375 snd_pcm_wait] is called, if polling has been specified in the command line arguments;		*** [http://www.alsa-project.org/alsa-doc/alsa-lib/group___p_c_m.html#gad4d53d58b996a7cd9a5cbf1710b90375 snd_pcm_wait] is called, if polling has been specified in the command line arguments;
Line 262:		Line 264:

	See the source code for details of the <code>readbuf()</code> and <code>writebuf()</code> functions - which may involve loops of their own, but ultimately call <code>[http://www.alsa-project.org/alsa-doc/alsa-lib/group___p_c_m.html#ga4c2c7bd26cf221268d59dc3bbeb9c048 snd_pcm_readi]</code> and <code>[http://www.alsa-project.org/alsa-doc/alsa-lib/group___p_c_m.html#gabc748a500743713eafa960c7d104ca6f snd_pcm_writei]</code>, respectively.		See the source code for details of the <code>readbuf()</code> and <code>writebuf()</code> functions - which may involve loops of their own, but ultimately call <code>[http://www.alsa-project.org/alsa-doc/alsa-lib/group___p_c_m.html#ga4c2c7bd26cf221268d59dc3bbeb9c048 snd_pcm_readi]</code> and <code>[http://www.alsa-project.org/alsa-doc/alsa-lib/group___p_c_m.html#gabc748a500743713eafa960c7d104ca6f snd_pcm_writei]</code>, respectively.


	=== '''Mailing list notes''' ===		=== '''Mailing list notes''' ===

Sdaau: added quick overview section

2013-09-12T20:02:02Z

added quick overview section

← Older revision		Revision as of 20:02, 12 September 2013
Line 244:		Line 244:
	Hardware sync		Hardware sync
	</pre></small>		</pre></small>


			=== '''Quick overview''' ===

			In brief, the <code>latency.c</code> 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 <code>showlatency()</code> function - which ultimately prints the "<i>Trying latency %li frames ...</i>" line
			** calls [http://www.alsa-project.org/alsa-doc/alsa-lib/group___p_c_m.html#gac6c33091b049985baa6466e8fe93917e snd_pcm_link] on the capture and playback stream file descriptors, to have them "<i>start/stop/prepare in sync</i>"
			** calls <code>snd_pcm_format_set_silence</code>, and then
			** calls <code>writebuf(phandle, buffer, latency ...)</code> '''''twice'''''
			** starts yet another <code>while</code> loop, where:
			*** [http://www.alsa-project.org/alsa-doc/alsa-lib/group___p_c_m.html#gad4d53d58b996a7cd9a5cbf1710b90375 snd_pcm_wait] is called, if polling has been specified in the command line arguments;
			*** <code>r = readbuf(chandle, buffer, latency, ...)</code> is called on the capture stream
			*** <code>writebuf(phandle, buffer, r, ...)</code> is called on the playback stream

			See the source code for details of the <code>readbuf()</code> and <code>writebuf()</code> functions - which may involve loops of their own, but ultimately call <code>[http://www.alsa-project.org/alsa-doc/alsa-lib/group___p_c_m.html#ga4c2c7bd26cf221268d59dc3bbeb9c048 snd_pcm_readi]</code> and <code>[http://www.alsa-project.org/alsa-doc/alsa-lib/group___p_c_m.html#gabc748a500743713eafa960c7d104ca6f snd_pcm_writei]</code>, respectively.

Sdaau: inited page

2013-08-18T11:06:52Z

inited page

New page

__FORCETOC__
== test latency.c ==

Within <code>alsa-lib</code>, there is a utility, [http://git.alsa-project.org/?p=alsa-lib.git;a=blob;f=test/latency.c; test/latency.c] ([http://git.alsa-project.org/?p=alsa-lib.git;a=history;f=test/latency.c; history]), which performs a full-duplex test, where recorded (captured) data is played back.

From <code>alsa-lib/test/latency.c</code>:

<pre>
* 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.
</pre>

=== '''Building''' ===

The name of the executable has to be passed explicitly to the <code>make</code> command - via [http://thread.gmane.org/gmane.linux.alsa.devel/6746/focus=6750 Re: problem ragarding execution of Latency.c (alsa-devel)]:

<pre>
cd alsa-lib/test
make latency
</pre>

=== '''Options''' ===

<pre>
$ ./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
</pre>

Notes:
* The option <code>-F,--frames</code> seems not to be handled anywhere in the code, and as such has no effect.
* The "Tip #1" refers to an option <code>-t</code> which doesn't exist - however, it is likely a typo for the option <code>-s</code> for duration in seconds
* The option <code>-s</code> 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 <code>-B</code> and <code>-E</code> are not recognized ("invalid option") - but the long options <code>--buffer</code> and <code>--period</code> still work even then.

=== '''Usage''' ===

When called, the <code>test/latency.c</code> program will attemp to set period/buffer sizes based on the latency entered, starting from <code>-m,--min</code> 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 <code>-M,--max</code> latency is reached.

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

<pre>
$ 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
</pre>

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

<pre>
$ 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...
...
</pre>

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

<pre>
$ 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
</pre>

=== '''Mailing list notes''' ===

[http://thread.gmane.org/gmane.linux.alsa.devel/17014 latency.c: some feature requests (alsa-devel)] (2004-11-28)
<pre>
> 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.
</pre>

[http://thread.gmane.org/gmane.linux.alsa.devel/37367 latency.c and delay related questions (alsa-devel)] (2006-06-20)
<pre>
> 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.
</pre>

=== '''Meaning of --buffer and --period''' ===

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

* The latency parameter, derived from <code>-m/--min</code> and <code>-M/--max</code> parameters, ultimately translates to the PCM buffer_size
* Specifying <code>--buffer</code> 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 <code>-m/--min</code> and <code>-M/--max</code>
* Specifying <code>--period</code> 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 <code>printf</code> statements to the <code>setparams_bufsize</code> function:

<pre>
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;
}
</pre>

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

<pre>
$ ./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)
</pre>

Note that the "device does not support 2 periods per buffer" message comes from a revision to <code>latency.c</code> 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 <code>-m/--min</code> and <code>-M/--max</code> 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 <code>-m 64 -M 128</code> or <code>-m 64 -M 128</code>:

<pre>
$ ./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
</pre>

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 <code>grep</code> 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 <code>strace</code>:

<pre>
$ 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) ---
</pre>

... which tells us that the program gets stuck on an <code>ioctl</code> 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 <code>gdb</code> debugger; wait for it to lock - and when it does, we can issue Ctrl-C to break into the program, and then issue <code>bt</code> to obtain a backtrace.

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

So, the <code>gdb</code> session would look like this:

<pre>
$ 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
</pre>

... which confirms that the failing <code>ioctl</code> is due to a <code>snd_pcm_writei</code> call.