Project

General

Profile

Bug #5024

Timing Advance loop is broken for SDCCH channels

Added by fixeria 8 months ago. Updated 8 months ago.

Status:
Resolved
Priority:
Normal
Assignee:
Category:
osmo-bts-trx
Target version:
-
Start date:
02/15/2021
Due date:
% Done:

100%

Spec Reference:

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?

Associated revisions

Revision d37041b1 (diff)
Added by fixeria 8 months ago

ta_control: make 'struct bts_ul_meas' parameters const

The only reason why it was not 'const' is that in lchan_new_ul_meas()
we may need to overwrite 'ulm->is_sub'. This can still be done after
memcpy()ing a new set of samples to the destination buffer.

Change-Id: I0cabf75f8e0bf793c01225a4a8433e994c93f562
Related: OS#5024

Revision 8777b63e (diff)
Added by fixeria 8 months ago

ta_control: fix Timing Advance control for SDCCH channels

The check in lchan_ms_ta_ctrl() breaks Timing Advance control on
SDCCH channels, because 'num_ul_meas' wraps and never reaches 4.
Neither this check makes any sense for other channel types,
because lchan_ms_ta_ctrl() is always called in the end of the
measurement period. Let's drop it.

Change-Id: I0b86d49ec00b38d0f309c56b2519e5d487f0b65b
Fixes: If7ddf74db3abc9b9872abe620a0aeebe3327e70a
Related: OS#5024

History

#1 Updated by fixeria 8 months 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.

#2 Updated by fixeria 8 months 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.

#3 Updated by laforge 8 months 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.

#4 Updated by fixeria 8 months 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.

#5 Updated by fixeria 8 months ago

  • Status changed from In Progress to Resolved
  • % Done changed from 80 to 100

The fix has been merged.

Also available in: Atom PDF

Add picture from clipboard (Maximum size: 48.8 MB)