Test latency.c: Difference between revisions
Jump to navigation
Jump to search
(inited page) |
(→Quick overview: - added clarification about "Trying latency ..." line) |
||
| (One intermediate revision by the same user not shown) | |||
| Line 245: | Line 245: | ||
</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 | |||
*** <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 <code>snd_pcm_format_set_silence</code>, and then | |||
** 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: | |||
*** [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. | |||
=== '''Mailing list notes''' === | === '''Mailing list notes''' === | ||
Latest revision as of 05:45, 18 September 2013
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,--framesseems not to be handled anywhere in the code, and as such has no effect. - The "Tip #1" refers to an option
-twhich doesn't exist - however, it is likely a typo for the option-sfor duration in seconds - The option
-sfor 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
-Band-Eare not recognized ("invalid option") - but the long options--bufferand--periodstill 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 thelatencyinput argument by two (latency *= 2;); so if the printout says "Trying latency 128 frames ...", that means thatlatencyparameter is actually 64
- Note: the
- 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
latencyis twice smaller than what the printout "Trying latency %li frames ..." says - callingwritebuf()twice, means that we ultimately achieve the demanded latency, as shown on the printout.
- Note: since the value of the variable
- starts yet another
whileloop, 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 streamwritebuf(phandle, buffer, r, ...)is called on the playback stream
- shows the current latency value, using the
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/--minand-M/--maxparameters, ultimately translates to the PCM buffer_size - Specifying
--bufferultimately 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/--minand-M/--max - Specifying
--perioddoes 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.