[Linphone-developers] Distorted audio & increasing clock skew

Hello,

I have a setup using a Raspberry Pi Compute Model 3+ (basically the same thing as the 3B+ but in a different form factor and with external USB audio) where after several hours of an open VoIP call, the audio becomes choppy and/or distorted (I can post an audio recording if that helps). If the call is discontinued and re-established, the audio becomes normal again. Looking at the logs I see the “wall clock skew” rapidly increasing so I assume the two are related. Can anyone tell me how to prevent the clock skew from increasing?

I’m using ALSA (PulseAudio is NOT installed). I have tried installing and configuring PulseAudio but I still saw the clock skew problem so I abandoned that change (admittedly, I didn’t confirm the audio distorted over time). I’ve also found that if I starve linphone from CPU cycles (e.g. compress a large file in a priority thread), linphone throws several errors that result in the audio being ‘fixed’.

OS: Raspbian 10 (Buster)

Kernel: 5.4.51-v7+

Application: linphone-daemon 4.4.0-alpha-73-gb5b2a5bf6 (compiled for Raspberry Pi)

Log Excerpt #1 – Audio is distorted

###############

2021-11-02 10:36:34:776 mediastreamer-message-sound/wall clock skew is average=235210.129590 ms

2021-11-02 10:36:35:530 liblinphone-message-Bandwidth usage for CallSession [0x6fc7c804]:

Stream #0 (audio) | cpu: 11.59% | RTP : [d=77.67,u=80.53] RTCP: [d=0.00,u=0.00] (kbits/sec)

2021-11-02 10:36:35:915 belle-sip-message-channel [0x6fc012c0]: keep alive sent to [UDP://10.0.15.220:5060]

2021-11-02 10:36:36:376 mediastreamer-message-sound/wall clock skew is average=235216.114823 ms

2021-11-02 10:36:36:540 liblinphone-message-Bandwidth usage for CallSession [0x6fc7c804]:

Stream #0 (audio) | cpu: 9.08% | RTP : [d=73.78,u=78.63] RTCP: [d=0.00,u=0.00] (kbits/sec)

2021-11-02 10:36:36:601 mediastreamer-message-MSAudio stream [0x6fcc4ec8]: receiving RTCP SR

2021-11-02 10:36:36:601 mediastreamer-message-MSSimpleQosAnalyzer: lost_percentage=0.000000, int_jitter=9.000000 ms, rt_prop=0.007370 sec

2021-11-02 10:36:36:601 mediastreamer-message-MSSimpleQosAnalyzer: everything is fine.

2021-11-02 10:36:36:601 mediastreamer-message-MSBitrateController: current state is Init

2021-11-02 10:36:36:602 mediastreamer-message-MSQualityIndicator[0x6fc63548][audio], remote statistics available:

Loss rate : 0.0%

Inter-arrival jitter: 9.0ms

RT propagation : 7.4ms

2021-11-02 10:36:36:602 liblinphone-message-Linphone core [0x15d8bc8] notified [call_stats_updated]

2021-11-02 10:36:37:532 liblinphone-message-Bandwidth usage for CallSession [0x6fc7c804]:

Stream #0 (audio) | cpu: 12.73% | RTP : [d=76.95,u=78.43] RTCP: [d=0.04,u=0.00] (kbits/sec)

2021-11-02 10:36:37:996 mediastreamer-message-sound/wall clock skew is average=235222.618232 ms

2021-11-02 10:36:38:547 liblinphone-message-Bandwidth usage for CallSession [0x6fc7c804]:

Stream #0 (audio) | cpu: 13.20% | RTP : [d=72.05,u=80.66] RTCP: [d=0.00,u=0.00] (kbits/sec)

2021-11-02 10:36:39:105 ortp-message-jitter buffer stable: target-size: 500.000000 ms, effective-size: 1097.583984 (min: 40 nom: 60, max: 500)

2021-11-02 10:36:39:106 ortp-message-jitter buffer rls stats: count=2682121, clockrate=8000, offset=3814.04 clock_ratio=1.00381, capped_offset=3974 capped_clock_ratio=1.003807, max_ts_deviation=5800.000000 prev_max_ts_deviation=5799.000000, deviation=5743, RLS VARIABLES: P[0][0]=0.000000, P[1][0]=-0.000000, P[0][1]=-0.000000, P[1][1]=0.000001

2021-11-02 10:36:39:542 liblinphone-message-Bandwidth usage for CallSession [0x6fc7c804]:

Stream #0 (audio) | cpu: 11.98% | RTP : [d=28.73,u=78.51] RTCP: [d=0.00,u=0.00] (kbits/sec)

2021-11-02 10:36:39:596 mediastreamer-message-sound/wall clock skew is average=235229.125620 ms

2021-11-02 10:36:39:605 ortp-message-Sending RTCP SR compound message on session [0x6fc5c220].

2021-11-02 10:36:39:623 mediastreamer-message-MSAudio_stream_iterate[0x6fcc4ec8], local statistics available:

Local current jitter buffer size: 1220.0ms

2021-11-02 10:36:39:624 liblinphone-message-Linphone core [0x15d8bc8] notified [call_stats_updated]

2021-11-02 10:36:40:538 liblinphone-message-Bandwidth usage for CallSession [0x6fc7c804]:

Stream #0 (audio) | cpu: 10.58% | RTP : [d=46.48,u=79.95] RTCP: [d=0.00,u=1.15] (kbits/sec)

2021-11-02 10:36:41:196 mediastreamer-message-sound/wall clock skew is average=235235.448496 ms

2021-11-02 10:36:41:548 liblinphone-message-Bandwidth usage for CallSession [0x6fc7c804]:

Stream #0 (audio) | cpu: 12.21% | RTP : [d=80.42,u=80.67] RTCP: [d=0.00,u=0.00] (kbits/sec)

2021-11-02 10:36:41:609 mediastreamer-message-MSAudio stream [0x6fcc4ec8]: receiving RTCP SR

2021-11-02 10:36:41:609 mediastreamer-message-MSSimpleQosAnalyzer: lost_percentage=0.000000, int_jitter=9.000000 ms, rt_prop=0.007111 sec

2021-11-02 10:36:41:609 mediastreamer-message-MSSimpleQosAnalyzer: everything is fine.

2021-11-02 10:36:41:610 mediastreamer-message-MSBitrateController: current state is Init

2021-11-02 10:36:41:610 mediastreamer-message-MSQualityIndicator[0x6fc63548][audio], remote statistics available:

Loss rate : 0.0%

Inter-arrival jitter: 9.0ms

RT propagation : 7.1ms

2021-11-02 10:36:41:610 liblinphone-message-Linphone core [0x15d8bc8] notified [call_stats_updated]

2021-11-02 10:36:42:540 liblinphone-message-Bandwidth usage for CallSession [0x6fc7c804]:

Stream #0 (audio) | cpu: 10.22% | RTP : [d=75.83,u=79.81] RTCP: [d=0.04,u=0.00] (kbits/sec)

2021-11-02 10:36:42:816 mediastreamer-message-sound/wall clock skew is average=235241.548289 ms

2021-11-02 10:36:43:531 liblinphone-message-Bandwidth usage for CallSession [0x6fc7c804]:

Stream #0 (audio) | cpu: 11.64% | RTP : [d=79.42,u=79.40] RTCP: [d=0.00,u=0.00] (kbits/sec)

2021-11-02 10:36:44:126 ortp-message-jitter buffer stable: target-size: 500.000000 ms, effective-size: 1219.991943 (min: 40 nom: 60, max: 500)

2021-11-02 10:36:44:126 ortp-message-jitter buffer rls stats: count=2682322, clockrate=8000, offset=3813.17 clock_ratio=1.00381, capped_offset=3973 capped_clock_ratio=1.003807, max_ts_deviation=5832.000000 prev_max_ts_deviation=5814.000000, deviation=5778, RLS VARIABLES: P[0][0]=0.000000, P[1][0]=-0.000000, P[0][1]=-0.000000, P[1][1]=0.000001

2021-11-02 10:36:44:416 mediastreamer-message-sound/wall clock skew is average=235247.602330 ms

2021-11-02 10:36:44:544 liblinphone-message-Bandwidth usage for CallSession [0x6fc7c804]:

Stream #0 (audio) | cpu: 8.18% | RTP : [d=74.31,u=79.95] RTCP: [d=0.00,u=0.00] (kbits/sec)

2021-11-02 10:36:45:541 liblinphone-message-Bandwidth usage for CallSession [0x6fc7c804]:

Stream #0 (audio) | cpu: 11.34% | RTP : [d=75.43,u=79.91] RTCP: [d=0.00,u=0.00] (kbits/sec)

2021-11-02 10:36:45:567 ortp-message-Sending RTCP SR compound message on session [0x6fc5c220].

2021-11-02 10:36:45:582 mediastreamer-message-MSAudio_stream_iterate[0x6fcc4ec8], local statistics available:

Local current jitter buffer size: 1122.5ms

2021-11-02 10:36:45:582 liblinphone-message-Linphone core [0x15d8bc8] notified [call_stats_updated]

2021-11-02 10:36:45:928 belle-sip-message-channel [0x6fc012c0]: keep alive sent to [UDP://10.0.15.220:5060]

2021-11-02 10:36:46:015 mediastreamer-message-sound/wall clock skew is average=235253.791877 ms

2021-11-02 10:36:46:533 liblinphone-message-Bandwidth usage for CallSession [0x6fc7c804]:

Stream #0 (audio) | cpu: 8.14% | RTP : [d=78.85,u=79.40] RTCP: [d=0.00,u=1.14] (kbits/sec)

###############

Log Excerpt #2 – Audio is okay (during and after creating aforementioned compressed file)

###############

2021-11-02 10:36:55:436 ortp-message-Sending RTCP SR compound message on session [0x6fc5c220].

2021-11-02 10:36:55:447 mediastreamer-message-MSAudio_stream_iterate[0x6fcc4ec8], local statistics available:

Local current jitter buffer size: 1220.5ms

2021-11-02 10:36:55:447 liblinphone-message-Linphone core [0x15d8bc8] notified [call_stats_updated]

2021-11-02 10:36:55:549 liblinphone-message-Bandwidth usage for CallSession [0x6fc7c804]:

Stream #0 (audio) | cpu: 9.08% | RTP : [d=74.44,u=78.38] RTCP: [d=0.00,u=0.00] (kbits/sec)

2021-11-02 10:36:55:941 mediastreamer-message-sound/wall clock skew is average=235291.286966 ms

2021-11-02 10:36:55:941 mediastreamer-error-snd_pcm_avail_update: Broken pipe

2021-11-02 10:36:55:941 mediastreamer-error-*** alsa_can_read fixup, trying to recover

2021-11-02 10:36:55:941 mediastreamer-message-alsa error in pcm.c:8424 - overrun occurred

2021-11-02 10:36:55:941 mediastreamer-message-Recovery done

2021-11-02 10:36:55:942 mediastreamer-warning-MSAudio MSTicker: We are late of 277 miliseconds.

2021-11-02 10:36:55:961 belle-sip-message-channel [0x6fc012c0]: keep alive sent to [UDP://10.0.15.220:5060]

2021-11-02 10:36:55:986 mediastreamer-message-Adjusting output timestamp by 2400

2021-11-02 10:36:56:547 liblinphone-message-Bandwidth usage for CallSession [0x6fc7c804]:

Stream #0 (audio) | cpu: 9.50% | RTP : [d=0.90,u=61.00] RTCP: [d=0.00,u=1.02] (kbits/sec)

2021-11-02 10:36:56:725 mediastreamer-message-MSAudio stream [0x6fcc4ec8]: receiving RTCP SR

2021-11-02 10:36:56:725 mediastreamer-message-MSSimpleQosAnalyzer: lost_percentage=0.000000, int_jitter=13.000000 ms, rt_prop=0.017166 sec

2021-11-02 10:36:56:725 mediastreamer-message-MSSimpleQosAnalyzer: everything is fine.

2021-11-02 10:36:56:725 mediastreamer-message-MSBitrateController: current state is Init

2021-11-02 10:36:56:725 mediastreamer-message-MSQualityIndicator[0x6fc63548][audio], remote statistics available:

Loss rate : 0.0%

Inter-arrival jitter: 13.0ms

RT propagation : 17.2ms

2021-11-02 10:36:56:726 liblinphone-message-Linphone core [0x15d8bc8] notified [call_stats_updated]

2021-11-02 10:36:57:536 liblinphone-message-Bandwidth usage for CallSession [0x6fc7c804]:

Stream #0 (audio) | cpu: 10.91% | RTP : [d=80.78,u=78.16] RTCP: [d=0.04,u=0.00] (kbits/sec)

2021-11-02 10:36:57:625 mediastreamer-message-sound/wall clock skew is average=235487.648910 ms

2021-11-02 10:36:58:537 liblinphone-message-Bandwidth usage for CallSession [0x6fc7c804]:

Stream #0 (audio) | cpu: 11.28% | RTP : [d=81.30,u=80.09] RTCP: [d=0.00,u=0.00] (kbits/sec)

2021-11-02 10:36:59:166 mediastreamer-message-sound/wall clock skew is average=235563.934602 ms

###############

Any insight would be greatly appreciated.

Regards,

Nathan Neufeldt

From:	Nathan Neufeldt
Subject:	[Linphone-developers] Distorted audio & increasing clock skew
Date:	Tue, 2 Nov 2021 14:48:42 +0000