Re: [Linphone-developers] Voice delay increasing during call

[宋智峰]

Hi,

 

The new founding is, every time we start to feel the obvious delay during the call, the warning "Audio MSTicker: We are late of xxx miliseconds." and Broken pipe error can be seen in the log. And with further debug info, we found the cause is, the MSTicker can be blocked for hundreds of mini-seconds insdide alsa_read_process() and alsa_write_process() for unknown reason, see below.

 

For analysis, we print more debug lines in filters' process: alsa_read_process(), alsa_write_process(), RTP sender_process() and receiver_process() , to learn when to enter into the filter process, when to exit, and the number of packets handled.

 

With the detailed logging, we can generally see the filter process work on received packets and exit immediately. However we see the alsa_read_process() blocked sometimes, like this:

 

[20160112-16:00:14.441] [message] Enter RTP receiver process ...
[20160112-16:00:14.441] [message] Jitter buffer count: 251
[20160112-16:00:14.441] [message] Sending RTCP SR compound message on session [0x46cad0].
[20160112-16:00:14.442] [message] ##### Receive 10698 RTP packets.
[20160112-16:00:14.442] [message] Exit receiver prcoess.
[20160112-16:00:14.442] [message] Enter alsa write process ...
[20160112-16:00:14.442] [message] ----- alsa write start ...
[20160112-16:00:14.442] [message] 1280 available to write
[20160112-16:00:14.442] [message] Write 10704 packets and 320 bytes for playback
[20160112-16:00:14.442] [message] Exit alsa write.
[20160112-16:00:14.446] [message] audio_stream_iterate[0x46b0c0]: local statistics available
 Local's current jitter buffer size:66.374504 ms
[20160112-16:00:14.450] [message] Enter alsa read process ...
[20160112-16:00:14.995] [message] ^^^^^ Alsa can read?
[20160112-16:00:14.998] [message]  available frames: 2560
[20160112-16:00:14.998] [error] snd_pcm_avail_update: Broken pipe
[20160112-16:00:14.998] [error] *** alsa_can_read fixup, trying to recover
[20160112-16:00:14.999] [message] Recovery done
[20160112-16:00:14.999] [message] Exit alsa read process ...
[20160112-16:00:14.999] [message] Enter RTP sender process ...
[20160112-16:00:14.999] [message] Exit sender process.
[20160112-16:00:14.999] [message] Enter RTP receiver process ...
[20160112-16:00:14.999] [message] ##### Receive 10699 RTP packets.
[20160112-16:00:14.000] [message] Exit receiver prcoess.
[20160112-16:00:14.000] [message] Enter alsa write process ...
[20160112-16:00:14.000] [message] ----- alsa write start ...
[20160112-16:00:14.000] [message] -32 available to write
[20160112-16:00:14.000] [warning] snd_pcm_writei(): EPIPE error
[20160112-16:00:14.000] [message] Write 10705 packets and 320 bytes for playback
[20160112-16:00:14.000] [message] Exit alsa write.
[20160112-16:00:15.000] [warning] Audio MSTicker: We are late of 540 miliseconds.

 

There is 545ms gap between the start point of alsa_read_process() and alsa_can_read(), see red lines above.

 

The related lines in alsa_read_process() as below:

 

void alsa_read_process(MSFilter *obj){
 AlsaReadData *ad=(AlsaReadData*)obj->data;
 int samples=(160*ad->rate)/8000;
 int err;
 mblk_t *om=NULL;
 if (ad->handle==NULL && ad->pcmdev!=NULL){
  ad->handle=alsa_open_r(ad->pcmdev,16,ad->nchannels==2,ad->rate);
  if (ad->handle){
   ad->read_samples=0;
   ms_ticker_set_time_func(obj->ticker,(uint64_t (*)(void*))ms_ticker_synchronizer_get_corrected_time, ad->ticker_synchronizer);
   rd_handle=ad->handle;
  }
 }
 if (ad->handle==NULL) return;

 

 ms_message("Enter alsa read process ...");

 

 while (alsa_can_read(ad->handle)>=samples){

 

And the related in alsa_can_read():

 

static int alsa_can_read(snd_pcm_t *dev)
{
 snd_pcm_sframes_t avail;
 int err;

 

 ms_message("^^^^^ Alsa can read?");

 

 alsa_resume(dev);
 avail = snd_pcm_avail_update(dev);
 ms_message(" available frames: %d", avail);

 

From the code lines, we don't see anyting can block the process. So please could you help on this: why does this gap happen? 

 

Acutually there are several points indicating the same problem (time gap), like below (84ms gap):

 

[20160112-15:57:09.320] [message] Enter alsa read process ...
[20160112-15:57:09.404] [message] ^^^^^ Alsa can read?
[20160112-15:57:09.406] [message]  available frames: 960 

 

You hints are very appreciated.

 

Thanks and regards,

Frank

宋智峰

---

发件人："宋智峰"<address@hidden>

发送时间：2015-12-14 17:19

主题：[Linphone-developers] Voice delay increasing during call

收件人："linphone-developers"<address@hidden>

抄送：

 

Hi,

 

We have ported Linphone 3.7.0 to an ARM board with Freescale i.MX6 running on Yocot Linux. Everything looks fine, only that the voice delay is increasing during the call. For example, make call from normal IP phone to Linphone, after 2 hours, while talking on IP phone, the voice heard from Linphone has obvious delay (should >1s).

 

We are trying to find out the cause. One finding is, the clock skew is also increasing: at the call beginning the clock skew is -9.45ms, but 3 hours later, it becomes 3229ms and jitter buffer size is shown as 720ms (adatptive jitter buffer is turned off), as the linphone log shown below: 

 

[20151214-11:54:24.020] [message] bandwidth usage for call [0xfbef60]: audio=[d=80.5,u=81.0] video=[d=532.7,u=621.5] kbit/sec
[20151214-11:54:24.020] [message] Thread processing load: audio=17.863424 video=3.797420
[20151214-11:54:24.303] [message] sound/wall clock skew is average=-9.459320 ms
[20151214-11:54:25.009] [message] bandwidth usage for call [0xfbef60]: audio=[d=80.1,u=80.6] video=[d=521.0,u=611.6] kbit/sec
[20151214-11:54:25.009] [message] Thread processing load: audio=20.526340 video=4.368080
[20151214-11:54:25.281] [message] Sending RTCP SR compound message on session [0xfe6338].
[20151214-11:54:25.298] [message] audio_stream_iterate[0xfe7278]: local statistics available
 Local's current jitter buffer size:39.360001 ms
[20151214-11:54:25.383] [message] Sending RTCP SR compound message on session [0xfdf8a0].
[20151214-11:54:25.401] [message] video_stream_iterate[0xf7e6b0]: local statistics available
 Local's current jitter buffer size:69.177124 ms

 

... ...

 

[20151214-15:01:31.018] [message] bandwidth usage for call [0xfbef60]: audio=[d=80.8,u=81.3] video=[d=559.3,u=583.3] kbit/sec
[20151214-15:01:31.018] [message] Thread processing load: audio=17.859980 video=4.901045
[20151214-15:01:31.351] [message] Sending RTCP SR compound message on session [0xfe6338].
[20151214-15:01:31.366] [message] audio_stream_iterate[0xfe7278]: local statistics available
 Local's current jitter buffer size:720.000000 ms
[20151214-15:01:31.542] [message] sound/wall clock skew is average=3229.025896 ms
[20151214-15:01:32.002] [message] bandwidth usage for call [0xfbef60]: audio=[d=79.4,u=80.8] video=[d=556.4,u=579.4] kbit/sec
[20151214-15:01:32.002] [message] Thread processing load: audio=21.201956 video=5.428172
[20151214-15:01:33.006] [message] bandwidth usage for call [0xfbef60]: audio=[d=81.6,u=82.1] video=[d=564.9,u=590.2] kbit/sec
[20151214-15:01:33.006] [message] Thread processing load: audio=19.752945 video=5.418468
[20151214-15:01:33.543] [message] sound/wall clock skew is average=3229.011706 ms

 

Not sure the long clock skew is related to the voice delay issue, so any hints is appreciated.

 

Thanks and regards,

Frank

 

  

 

 

 

     

 

 

2015-12-14

---

宋智峰