Bug #5024
closedTiming Advance loop is broken for SDCCH channels
100%
Description
My intention was to test the reactivity of the Timing Advance loop and investigate potential use of the 'P_CON_INTERVAL' parameter for making the loop more stable (we recently implemented it for MS/BS Power control). I set up a GSM network, connected an MS, and established a long-living SDCCH channel for testing using OsmoHLR's 'test-idle' USSD handler. To my surprise with 'DLOOP' category being set to 'debug' I could not see any messages related to the Timing Advance control in the log.
I quickly implemented a VTY command for delay simulation in osmo-bts, and tried to fake ToA=256 and ToA=512 for an active SDCCH connection. Neither this affected the logging (still nothing), nor could I see a different value reported to the BSC over A-bis/RSL. Time to check the source code!
void lchan_ms_ta_ctrl(struct gsm_lchan *lchan)
{
int16_t toa256 = lchan->meas.ms_toa256;
/* Do not perform any computation when the amount of measurement
* results is too little. */
if (lchan->meas.num_ul_meas < 4)
return;
if (toa256 < -TOA256_9OPERCENT && lchan->rqd_ta > TOA_MIN) {
LOGPLCHAN(lchan, DLOOP, LOGL_INFO,
"TOA is too early (%d), now lowering TA from %d to %d\n",
toa256, lchan->rqd_ta, lchan->rqd_ta - 1);
lchan->rqd_ta--;
} else if (toa256 > TOA256_9OPERCENT && lchan->rqd_ta < TOA_MAX) {
LOGPLCHAN(lchan, DLOOP, LOGL_INFO,
"TOA is too late (%d), now raising TA from %d to %d\n",
toa256, lchan->rqd_ta, lchan->rqd_ta + 1);
lchan->rqd_ta++;
} else
LOGPLCHAN(lchan, DLOOP, LOGL_DEBUG,
"TOA is correct (%d), keeping current TA of %d\n",
toa256, lchan->rqd_ta);
}
As can be seen, the code is expected to return early if the number of received measurements is too low. Most likely, the idea behind this is to give the MS some time to switch onto the recently allocated channel (although, I would say 4 SACCH periods or ~2 seconds is too much). A reasonable assumption here is that 'lchan->meas.num_ul_meas' never reaches 4, but why? Is it incremented at all?
Updated by fixeria about 3 years ago
- Status changed from New to In Progress
- % Done changed from 0 to 40
Setting 'DMEAS' to 'debug' gives the answer:
DRSL NOTICE rsl.c:1024 (bts=0,trx=0,ts=1,pchan=SDCCH8) (ss=0) SDCCH Tx CHAN ACT ACK DTRX INFO trx_if.c:644 phy0.0: Response message: 'RSP NOHANDOVER 0 1 0' DMEAS DEBUG scheduler_trx.c:557 Measurement AVG (num=4, shift=4): RSSI -50.000000, ToA256 0, C/I 0 cB DL1P NOTICE sched_lchan_xcch.c:120 1244163/938/11/18/03 (bts=0,trx=0,ts=1) SDCCH/8(0): Received incomplete data (69/102) DMEAS DEBUG scheduler_trx.c:557 Measurement AVG (num=4, shift=4): RSSI -48.000000, ToA256 33, C/I 77 cB DMEAS DEBUG measurement.c:344 1244211/938/07/15/51 (bts=0,trx=0,ts=1,ss=0) adding measurement (ber10k=0, ta_offs=33, ci=0.00, is_sub=1, rssi=-48), num_ul_meas=0, fn_mod=15 DLLAPD NOTICE lapd_core.c:949 ((bts=0,trx=0,ts=1,ss=0)[DCCH][0]) Store content res. DMEAS DEBUG scheduler_trx.c:557 Measurement AVG (num=4, shift=4): RSSI -48.000000, ToA256 47, C/I 75 cB DMEAS DEBUG measurement.c:344 1244243/938/13/47/31 (bts=0,trx=0,ts=1,ss=0) adding measurement (ber10k=0, ta_offs=47, ci=0.00, is_sub=1, rssi=-48), num_ul_meas=1, fn_mod=47 DMEAS DEBUG scheduler_trx.c:557 Measurement AVG (num=4, shift=4): RSSI -48.000000, ToA256 32, C/I 77 cB DMEAS DEBUG measurement.c:344 1244262/938/06/15/50 (bts=0,trx=0,ts=1,ss=0) adding measurement (ber10k=0, ta_offs=32, ci=0.00, is_sub=1, rssi=-48), num_ul_meas=2, fn_mod=66 DMEAS DEBUG measurement.c:291 (bts=0,trx=0,ts=1,ss=0) meas period end fn:1244262, fn_mod:66, status:1, pchan:SDCCH8 DMEAS DEBUG measurement.c:579 (bts=0,trx=0,ts=1,ss=0) Calculating measurement results for physical channel: SDCCH8 DMEAS DEBUG measurement.c:602 (bts=0,trx=0,ts=1,ss=0) Received 3 UL measurements, expected 3 <-- (!) DMEAS DEBUG measurement.c:662 (bts=0,trx=0,ts=1,ss=0) Received UL measurements contain 3 SUB measurements, expected 3 DMEAS DEBUG measurement.c:671 (bts=0,trx=0,ts=1,ss=0) Replaced 0 measurements with dummy values, from which 0 were SUB measurements DMEAS INFO measurement.c:718 (bts=0,trx=0,ts=1,ss=0) Computed TA256( 37) BER-FULL( 0.00%), RSSI-FULL(- 48dBm), BER-SUB( 0.00%), RSSI-SUB(- 48dBm) DMEAS INFO measurement.c:733 (bts=0,trx=0,ts=1,ss=0) UL MEAS RXLEV_FULL(62), RXLEV_SUB(62), RXQUAL_FULL(0), RXQUAL_SUB(0), num_meas_sub(3), num_ul_meas(3) DMEAS DEBUG scheduler_trx.c:557 Measurement AVG (num=4, shift=4): RSSI -48.000000, ToA256 37, C/I 76 cB DMEAS DEBUG measurement.c:344 1244313/938/05/15/49 (bts=0,trx=0,ts=1,ss=0) adding measurement (ber10k=0, ta_offs=37, ci=0.00, is_sub=1, rssi=-48), num_ul_meas=0, fn_mod=15 DMEAS DEBUG scheduler_trx.c:557 Measurement AVG (num=4, shift=4): RSSI -48.000000, ToA256 43, C/I 76 cB DMEAS DEBUG measurement.c:344 1244345/938/11/47/29 (bts=0,trx=0,ts=1,ss=0) adding measurement (ber10k=0, ta_offs=43, ci=0.00, is_sub=1, rssi=-48), num_ul_meas=1, fn_mod=47 DMEAS DEBUG scheduler_trx.c:557 Measurement AVG (num=4, shift=4): RSSI -48.000000, ToA256 42, C/I 76 cB DMEAS DEBUG measurement.c:344 1244364/938/04/15/48 (bts=0,trx=0,ts=1,ss=0) adding measurement (ber10k=0, ta_offs=42, ci=0.00, is_sub=1, rssi=-48), num_ul_meas=2, fn_mod=66 DMEAS DEBUG measurement.c:291 (bts=0,trx=0,ts=1,ss=0) meas period end fn:1244364, fn_mod:66, status:1, pchan:SDCCH8 DMEAS DEBUG measurement.c:579 (bts=0,trx=0,ts=1,ss=0) Calculating measurement results for physical channel: SDCCH8 DMEAS DEBUG measurement.c:602 (bts=0,trx=0,ts=1,ss=0) Received 3 UL measurements, expected 3 <-- (!) DMEAS DEBUG measurement.c:662 (bts=0,trx=0,ts=1,ss=0) Received UL measurements contain 3 SUB measurements, expected 3 DMEAS DEBUG measurement.c:671 (bts=0,trx=0,ts=1,ss=0) Replaced 0 measurements with dummy values, from which 0 were SUB measurements DMEAS INFO measurement.c:718 (bts=0,trx=0,ts=1,ss=0) Computed TA256( 40) BER-FULL( 0.00%), RSSI-FULL(- 48dBm), BER-SUB( 0.00%), RSSI-SUB(- 48dBm) DMEAS INFO measurement.c:733 (bts=0,trx=0,ts=1,ss=0) UL MEAS RXLEV_FULL(62), RXLEV_SUB(62), RXQUAL_FULL(0), RXQUAL_SUB(0), num_meas_sub(3), num_ul_meas(3)
The problem is that 'lchan->meas.num_ul_meas' wraps according to the expected number of measurements for particular channel, and in case of SDCCH8 it's 3. Therefore, Timing Advance control is never performed on SDCCH, affecting call establishment, SMS and SS/USSD. I was pretty sure we had TTCN-3 test cases for Timing Advance, but as it turns out we do not? Or the coverage is not significant. Otherwise we would have found this problem already.
Updated by fixeria about 3 years ago
- % Done changed from 40 to 80
remote: https://gerrit.osmocom.org/c/osmo-bts/+/22905 ta_control: cosmetic: use correct naming for MIN/MAX constraints [NEW]
remote: https://gerrit.osmocom.org/c/osmo-bts/+/22906 ta_control: make 'struct bts_ul_meas' parameters const [NEW]
remote: https://gerrit.osmocom.org/c/osmo-bts/+/22907 ta_control: fix Timing Advance control for SDCCH channels [NEW]
TODO: add proper commit message.
Updated by laforge about 3 years ago
this likely never showed up in practice, as only the loop is affected. The initial TA when establishing the SDCCH is set correct, and since SDCCH are typically short-lived chanenls, it's unlikely that you would actually move more than 500m before the LU/SMS is over, or before you've been assigned a TCH.
Updated by fixeria about 3 years ago
- Priority changed from High to Normal
laforge wrote:
this likely never showed up in practice, as only the loop is affected. The initial TA when establishing the SDCCH is set correct, and since SDCCH are typically short-lived chanenls, it's unlikely that you would actually move more than 500m before the LU/SMS is over, or before you've been assigned a TCH.
Yes, it's not as critical as I thought. The initial TA estimation is done by the BSC, and works as expected. Probably, only multi-part SMS or long-living USSD sessions are affected.
Updated by fixeria about 3 years ago
- Status changed from In Progress to Resolved
- % Done changed from 80 to 100
The fix has been merged.
