Actions
Bug #4461
closedRTP clock out of sync with lower layer
Start date:
03/19/2020
Due date:
% Done:
100%
Spec Reference:
Description
On a setup with current nightly osmo-trx-uhd + osmo-bts-trx, dexter and I am observing:
<000e> l1sap.c:143 (bts=0,trx=0,ts=1,ss=0) RTP clock out of sync with lower layer: 1440 vs 160 (934964->935003) <000e> l1sap.c:143 (bts=0,trx=0,ts=1,ss=0) RTP clock out of sync with lower layer: 82594400 vs 160 (935029->934999) <000e> l1sap.c:143 (bts=0,trx=0,ts=1,ss=0) RTP clock out of sync with lower layer: 1440 vs 160 (934999->935038) <000e> l1sap.c:143 (bts=0,trx=0,ts=1,ss=0) RTP clock out of sync with lower layer: 82594400 vs 160 (935038->935007) <000e> l1sap.c:143 (bts=0,trx=0,ts=1,ss=0) RTP clock out of sync with lower layer: 1440 vs 160 (935016->935055) <000e> l1sap.c:143 (bts=0,trx=0,ts=1,ss=0) RTP clock out of sync with lower layer: 82594400 vs 160 (935055->935025) <000e> l1sap.c:143 (bts=0,trx=0,ts=1,ss=0) RTP clock out of sync with lower layer: 1440 vs 160 (935025->935064) <000e> l1sap.c:143 (bts=0,trx=0,ts=1,ss=0) RTP clock out of sync with lower layer: 82594400 vs 160 (935064->935033) <000e> l1sap.c:143 (bts=0,trx=0,ts=1,ss=0) RTP clock out of sync with lower layer: 1440 vs 160 (935033->935072) <000e> l1sap.c:143 (bts=0,trx=0,ts=1,ss=0) RTP clock out of sync with lower layer: 82594400 vs 160 (935085->935055) <000e> l1sap.c:143 (bts=0,trx=0,ts=1,ss=0) RTP clock out of sync with lower layer: 1440 vs 160 (935055->935094) <0000> rsl.c:2946 (bts=0,trx=0,ts=2,ss=0) Handing RLL msg UNIT_DATA_IND from LAPDm to MEAS REP <000e> l1sap.c:143 (bts=0,trx=0,ts=1,ss=0) RTP clock out of sync with lower layer: 82594400 vs 160 (935103->935072) <000e> l1sap.c:143 (bts=0,trx=0,ts=1,ss=0) RTP clock out of sync with lower layer: 1440 vs 160 (935072->935111) <000e> l1sap.c:143 (bts=0,trx=0,ts=1,ss=0) RTP clock out of sync with lower layer: 82594400 vs 160 (935111->935081) <0006> scheduler_trx.c:1780 TRX Clock Ind: elapsed_us=1000033, elapsed_fn=217, error_us=-1422 <0006> scheduler_trx.c:1798 GSM clock jitter: -1944us (elapsed_fn=0) <000e> l1sap.c:143 (bts=0,trx=0,ts=1,ss=0) RTP clock out of sync with lower layer: 1440 vs 160 (935085->935124) <000e> l1sap.c:143 (bts=0,trx=0,ts=1,ss=0) RTP clock out of sync with lower layer: 82594400 vs 160 (935124->935094) <000e> l1sap.c:143 (bts=0,trx=0,ts=1,ss=0) RTP clock out of sync with lower layer: 1440 vs 160 (935098->935137) <000e> l1sap.c:143 (bts=0,trx=0,ts=1,ss=0) RTP clock out of sync with lower layer: 82594400 vs 160 (935155->935124) <000e> l1sap.c:143 (bts=0,trx=0,ts=1,ss=0) RTP clock out of sync with lower layer: 1440 vs 160 (935124->935163) <000e> l1sap.c:143 (bts=0,trx=0,ts=1,ss=0) RTP clock out of sync with lower layer: 82594400 vs 160 (935176->935146) <000e> l1sap.c:143 (bts=0,trx=0,ts=1,ss=0) RTP clock out of sync with lower layer: 1440 vs 160 (935150->935189) <0000> rsl.c:2946 (bts=0,trx=0,ts=2,ss=0) Handing RLL msg UNIT_DATA_IND from LAPDm to MEAS REP <000e> l1sap.c:143 (bts=0,trx=0,ts=2,ss=0) RTP clock out of sync with lower layer: 1440 vs 160 (935189->935228) <000e> l1sap.c:143 (bts=0,trx=0,ts=2,ss=0) RTP clock out of sync with lower layer: 82594400 vs 160 (935228->935198) <000e> l1sap.c:143 (bts=0,trx=0,ts=2,ss=0) RTP clock out of sync with lower layer: 1440 vs 160 (935241->935280) <000e> l1sap.c:143 (bts=0,trx=0,ts=2,ss=0) RTP clock out of sync with lower layer: 82594400 vs 160 (935280->935250) <000e> l1sap.c:143 (bts=0,trx=0,ts=1,ss=0) RTP clock out of sync with lower layer: 82594400 vs 160 (935289->935259) <000e> l1sap.c:143 (bts=0,trx=0,ts=1,ss=0) RTP clock out of sync with lower layer: 1440 vs 160 (935263->935302) <0000> rsl.c:2946 (bts=0,trx=0,ts=2,ss=0) Handing RLL msg UNIT_DATA_IND from LAPDm to MEAS REP <000e> l1sap.c:143 (bts=0,trx=0,ts=2,ss=0) RTP clock out of sync with lower layer: 1440 vs 160 (935280->935319) <000e> l1sap.c:143 (bts=0,trx=0,ts=2,ss=0) RTP clock out of sync with lower layer: 82594400 vs 160 (935319->935289) <000e> l1sap.c:143 (bts=0,trx=0,ts=1,ss=0) RTP clock out of sync with lower layer: 82594400 vs 160 (935324->935293) <000e> l1sap.c:143 (bts=0,trx=0,ts=1,ss=0) RTP clock out of sync with lower layer: 1440 vs 160 (935293->935332) <000e> l1sap.c:143 (bts=0,trx=0,ts=1,ss=0) RTP clock out of sync with lower layer: 82594400 vs 160 (935332->935302) <0006> scheduler_trx.c:1780 TRX Clock Ind: elapsed_us= 998155, elapsed_fn=216, error_us=+1315 <0006> scheduler_trx.c:1798 GSM clock jitter: -3260us (elapsed_fn=0) <000e> l1sap.c:143 (bts=0,trx=0,ts=1,ss=0) RTP clock out of sync with lower layer: 1440 vs 160 (935302->935341) <000e> l1sap.c:143 (bts=0,trx=0,ts=1,ss=0) RTP clock out of sync with lower layer: 82594400 vs 160 (935345->935315) <000e> l1sap.c:143 (bts=0,trx=0,ts=1,ss=0) RTP clock out of sync with lower layer: 1440 vs 160 (935315->935354) <000e> l1sap.c:143 (bts=0,trx=0,ts=2,ss=0) RTP clock out of sync with lower layer: 1440 vs 160 (935319->935358) <000e> l1sap.c:143 (bts=0,trx=0,ts=2,ss=0) RTP clock out of sync with lower layer: 82594400 vs 160 (935358->935328) <000e> l1sap.c:143 (bts=0,trx=0,ts=2,ss=0) RTP clock out of sync with lower layer: 1440 vs 160 (935341->935380) <000e> l1sap.c:143 (bts=0,trx=0,ts=2,ss=0) RTP clock out of sync with lower layer: 82594400 vs 160 (935380->935350) <000e> l1sap.c:143 (bts=0,trx=0,ts=1,ss=0) RTP clock out of sync with lower layer: 82594400 vs 160 (935402->935371) <000e> l1sap.c:143 (bts=0,trx=0,ts=1,ss=0) RTP clock out of sync with lower layer: 1440 vs 160 (935371->935410)What is obvious is that
- it's always the magic values 1440 / 82594400
- 1440 corresponds to 9 blocks of 160 clocks of our 8kHz sample clock
- frame numbers are jumping back and forth
<000e> l1sap.c:143 (bts=0,trx=0,ts=1,ss=0) RTP clock out of sync with lower layer: 1440 vs 160 (934964->935003) <000e> l1sap.c:143 (bts=0,trx=0,ts=1,ss=0) RTP clock out of sync with lower layer: 82594400 vs 160 (935029->934999) <000e> l1sap.c:143 (bts=0,trx=0,ts=1,ss=0) RTP clock out of sync with lower layer: 1440 vs 160 (934999->935038) <000e> l1sap.c:143 (bts=0,trx=0,ts=1,ss=0) RTP clock out of sync with lower layer: 82594400 vs 160 (935038->935007) <000e> l1sap.c:143 (bts=0,trx=0,ts=1,ss=0) RTP clock out of sync with lower layer: 1440 vs 160 (935016->935055) <000e> l1sap.c:143 (bts=0,trx=0,ts=1,ss=0) RTP clock out of sync with lower layer: 82594400 vs 160 (935055->935025) <000e> l1sap.c:143 (bts=0,trx=0,ts=1,ss=0) RTP clock out of sync with lower layer: 1440 vs 160 (935025->935064) <000e> l1sap.c:143 (bts=0,trx=0,ts=1,ss=0) RTP clock out of sync with lower layer: 82594400 vs 160 (935064->935033) <000e> l1sap.c:143 (bts=0,trx=0,ts=1,ss=0) RTP clock out of sync with lower layer: 1440 vs 160 (935033->935072) <000e> l1sap.c:143 (bts=0,trx=0,ts=1,ss=0) RTP clock out of sync with lower layer: 82594400 vs 160 (935085->935055)
this means we actually receive TCH data first for FN 935003, then advance to 935029 after which we receive TCH data for 934999. This is impossible and clearly indicates some problem in our scheduler.
Related issues
Actions
