[Linphone-developers] ALSA overrun errors for sr > 8000Hz

[Matteo Fortini]

I implemented a very simple ALSA->PCMU->RTP chain with mediastreamer2
(linphone 3.6.1 revision).

If I use a sample rate of 16000Hz, even on a fairly fast machine (Core
i7 laptop), I get this series of errors:

====================================================
ortp-message-ms_ticker_set_time_func: ticker's time method updated.
ortp-warning-mainticker: We are late of 65 miliseconds.
ortp-warning-mainticker: We are late of 175 miliseconds.
ortp-warning-mainticker: We are late of 425 miliseconds.
ortp-error-snd_pcm_avail_update: Broken pipe
ortp-error-*** alsa_can_read fixup, trying to recover
ALSA lib pcm.c:7843:(snd_pcm_recover) overrun occurred
ortp-message-Recovery done
ortp-message-Adjusting output timestamp by 0
ortp-warning-mainticker: We are late of 75 miliseconds.
ortp-warning-mainticker: We are late of 175 miliseconds.
ortp-warning-mainticker: We are late of 395 miliseconds.
ortp-error-snd_pcm_avail_update: Broken pipe
ortp-error-*** alsa_can_read fixup, trying to recover
ALSA lib pcm.c:7843:(snd_pcm_recover) overrun occurred
ortp-message-Recovery done
ortp-message-Adjusting output timestamp by -400
ortp-warning-mainticker: We are late of 66 miliseconds.
ortp-warning-mainticker: We are late of 175 miliseconds.
ortp-warning-mainticker: We are late of 405 miliseconds.
ortp-error-snd_pcm_avail_update: Broken pipe
ortp-error-*** alsa_can_read fixup, trying to recover
ALSA lib pcm.c:7843:(snd_pcm_recover) overrun occurred
ortp-message-Recovery done
ortp-message-Adjusting output timestamp by -1200
ortp-warning-mainticker: We are late of 65 miliseconds.
====================================================

The errors don't come up using 8000Hz.
I tracked down the problem to the two while loops in alsa.c and msrtp.c:
1) the samples come in in bursts, and in alsa.c the process takes some
time to take them off the buffer.
2) alsa enqueues a number of packets for the filters
3) the filters take some time to process the packets since they have
an unlimited loop, and this causes alsa to starve

This behavior is cyclical, and it won't go away, since one triggers the other.

I tried to fix it by applying the attached (very raw) patch, and it
seems to go in the right direction somehow, but the output now is:
=============================================
ortp-message-ms_ticker_set_time_func: ticker's time method updated.
ortp-warning-mainticker: We are late of 86 miliseconds.
ortp-warning-mainticker: We are late of 156 miliseconds.
ortp-warning-mainticker: We are late of 246 miliseconds.
ortp-warning-mainticker: We are late of 336 miliseconds.
ortp-warning-mainticker: We are late of 426 miliseconds.
ortp-warning-mainticker: We are late of 506 miliseconds.
ortp-warning-mainticker: We are late of 596 miliseconds.
ortp-warning-mainticker: We are late of 685 miliseconds.
ortp-warning-mainticker: We are late of 775 miliseconds.
ortp-warning-mainticker: We are late of 856 miliseconds.
ortp-warning-mainticker: We are late of 946 miliseconds.
ortp-warning-mainticker: We are late of 1036 miliseconds.
ortp-warning-mainticker: We are late of 1126 miliseconds.
ortp-warning-mainticker: We are late of 1216 miliseconds.
ortp-warning-mainticker: We are late of 1306 miliseconds.
ortp-warning-mainticker: We are late of 1396 miliseconds.
ortp-message-sound/wall clock skew is average=30.162762 ms
ortp-warning-mainticker: We are late of 1486 miliseconds.
ortp-warning-mainticker: We are late of 1565 miliseconds.
ortp-warning-mainticker: We are late of 1655 miliseconds.
ortp-warning-mainticker: We are late of 1746 miliseconds.
ortp-warning-mainticker: We are late of 1836 miliseconds.
ortp-warning-mainticker: We are late of 1926 miliseconds.
ortp-warning-mainticker: We are late of 2016 miliseconds.
ortp-warning-mainticker: We are late of 2106 miliseconds.
ortp-warning-mainticker: We are late of 2196 miliseconds.
ortp-warning-mainticker: We are late of 2286 miliseconds.
ortp-warning-mainticker: We are late of 2376 miliseconds.
ortp-warning-mainticker: We are late of 2455 miliseconds.
ortp-warning-mainticker: We are late of 2545 miliseconds.
ortp-warning-mainticker: We are late of 2636 miliseconds.
ortp-warning-mainticker: We are late of 2727 miliseconds.
ortp-warning-mainticker: We are late of 2816 miliseconds.
ortp-message-sound/wall clock skew is average=44.553021 ms
==============================================

and the RTP output is not so good, with timing problems.

I guess the whole mediastreamer2 alsa chain has been tested more with
8kHz sample rates than with the higher ones, and I can imagine some
improvements to it (e.g. not waiting for a full frame of samples
before reading from pcm in alsa.c, since the buffer may fill too
early), but was hoping someone more knowledgeable of the internals of
mediastreamer2 to be able to point me in the right direction.

Thank you in advance,
Matteo

0001-Added-a-limit-to-the-loops-in-alsa.c-and-msrtp.c-to-.patch
Description: Binary data