Project

General

Profile

Bug #4658

Wrong burst order in a multi-trx setup

Added by fixeria 26 days ago. Updated 18 days ago.

Status:
In Progress
Priority:
Urgent
Assignee:
Category:
TRX Toolkit
Target version:
-
Start date:
07/08/2020
Due date:
% Done:

80%

Resolution:
Spec Reference:

Description

While running the existing test cases from ttcn3-bts-test on hopping channels (see #4546), I noticed that sometimes trxcon starts to consume a lot of CPU power. As it turned out, this happens because the burst loss detection logic in trxcon somehow detects that the whole TDMA hyper-frame is lost, so it tries to substitute ~2715647 allegedly lost TDMA frames with a dummy burst. Of course it's a bug, because we're not supposed to compensate more than one TDMA multi-frame period. So the problem was a missing 'return' statement:

https://gerrit.osmocom.org/c/osmocom-bb/+/19183 trxcon/scheduler: subst_frame_loss(): print current TDMA fn
https://gerrit.osmocom.org/c/osmocom-bb/+/19184 trxcon/scheduler: fix subst_frame_loss(): do not compensate too much

However, I was interested to know what exactly tricks the burst detection logic to think that so many frames are lost.

/*! Return the difference of two specified TDMA frame numbers (subtraction) */
#define GSM_TDMA_FN_SUB(a, b) \
        ((a + GSM_TDMA_HYPERFRAME - b) % GSM_TDMA_HYPERFRAME)

/* How many frames elapsed since the last one? */
elapsed = GSM_TDMA_FN_SUB(fn, lchan->tdma.last_proc);
if (elapsed > mf->period) {
        LOGP(DSCHD, LOGL_NOTICE, "Too many (>%u) contiguous TDMA frames elapsed (%u) " 
                                 "since the last processed fn=%u (current %u)\n",
                                 mf->period, elapsed, lchan->tdma.last_proc, fn);
        return -EIO;
} else if (elapsed == 0) {
        LOGP(DSCHD, LOGL_ERROR, "No TDMA frames elapsed since the last processed " 
                                "fn=%u, must be a bug?\n", lchan->tdma.last_proc);
        return -EIO;
}

And slightly more informative logging message gives us a hint:

sched_trx.c:640 Too many (>104) contiguous TDMA frames elapsed (2715647) since the last processed fn=633 (current fn=632)

so, a burst with TDMA fn=632 is for some reason received late, since we already received a burst with TDMA fn=633.

This is definitely unexpected, and of course subtraction would result in a huge number: ((632 + 2715648) - 633) % 2715648 == 2715647.

trxd_order.pcapng trxd_order.pcapng 14.8 KB fixeria, 07/08/2020 01:32 PM

Related issues

Blocks OsmoBTS - Feature #4546: baseband frequency hopping support for osmo-bts-trxFeedback05/12/2020

History

#1 Updated by fixeria 26 days ago

  • Blocks Feature #4546: baseband frequency hopping support for osmo-bts-trx added

#2 Updated by pespin 26 days ago

That can probably be solved by:
  • If last processed FN is higher than the one received, increment counter, log error and don't enqueue it.
  • When enqueueing, make sure it is included in the correct place in the linked list of the queue, so that content is always sorted by FN.

#3 Updated by fixeria 26 days ago

so, a burst with TDMA fn=632 is for some reason received late, since we already received a burst with TDMA fn=633.

This is how it looks like in Wireshark (BTS sends from {5802,5804,5806,5808}, fake_trx.py - from 6702):

# Normal bursts on C0 (dummy bursts are sent later)
    1 0.000000000    127.0.0.1 → 127.0.0.1    OsmoTRXD 196 Tx burst (L1 -> TRX): TDMA FN 0000630 TN 0, Modulation GMSK  udp.srcport == 5802
    2 0.000025422    127.0.0.1 → 127.0.0.1    OsmoTRXD 196 Tx burst (L1 -> TRX): TDMA FN 0000630 TN 3, Modulation GMSK  udp.srcport == 5806

# Dummy bursts on C0
    3 0.000061862    127.0.0.1 → 127.0.0.1    OsmoTRXD 196 Tx burst (L1 -> TRX): TDMA FN 0000630 TN 1, Modulation GMSK  udp.srcport == 5802
    4 0.000072229    127.0.0.1 → 127.0.0.1    OsmoTRXD 196 Tx burst (L1 -> TRX): TDMA FN 0000630 TN 2, Modulation GMSK  udp.srcport == 5802
    5 0.000081210    127.0.0.1 → 127.0.0.1    OsmoTRXD 196 Tx burst (L1 -> TRX): TDMA FN 0000630 TN 3, Modulation GMSK  udp.srcport == 5802
    6 0.000090229    127.0.0.1 → 127.0.0.1    OsmoTRXD 196 Tx burst (L1 -> TRX): TDMA FN 0000630 TN 4, Modulation GMSK  udp.srcport == 5802
    7 0.000099617    127.0.0.1 → 127.0.0.1    OsmoTRXD 196 Tx burst (L1 -> TRX): TDMA FN 0000630 TN 5, Modulation GMSK  udp.srcport == 5802
    8 0.000109492    127.0.0.1 → 127.0.0.1    OsmoTRXD 196 Tx burst (L1 -> TRX): TDMA FN 0000630 TN 6, Modulation GMSK  udp.srcport == 5802
    9 0.000119187    127.0.0.1 → 127.0.0.1    OsmoTRXD 196 Tx burst (L1 -> TRX): TDMA FN 0000630 TN 7, Modulation GMSK  udp.srcport == 5802

# fake_trx.py forwards a burst with fn=630 (ok)
   10 0.000426474    127.0.0.1 → 127.0.0.1    OsmoTRXD 200 Rx burst (TRX -> L1): TDMA FN 0000630 TN 3  udp.srcport == 6702

# Normal bursts on C0 (dummy bursts are sent later)
   16 0.003762460    127.0.0.1 → 127.0.0.1    OsmoTRXD 196 Tx burst (L1 -> TRX): TDMA FN 0000631 TN 0, Modulation GMSK  udp.srcport == 5802
# A Normal burst on TRX3 (baseband freq. hopping)
   17 0.003788406    127.0.0.1 → 127.0.0.1    OsmoTRXD 196 Tx burst (L1 -> TRX): TDMA FN 0000631 TN 3, Modulation GMSK  udp.srcport == 5808

# Dummy bursts on C0
   18 0.003809389    127.0.0.1 → 127.0.0.1    OsmoTRXD 196 Tx burst (L1 -> TRX): TDMA FN 0000631 TN 1, Modulation GMSK  udp.srcport == 5802
   19 0.003819225    127.0.0.1 → 127.0.0.1    OsmoTRXD 196 Tx burst (L1 -> TRX): TDMA FN 0000631 TN 2, Modulation GMSK  udp.srcport == 5802
   20 0.003828888    127.0.0.1 → 127.0.0.1    OsmoTRXD 196 Tx burst (L1 -> TRX): TDMA FN 0000631 TN 3, Modulation GMSK  udp.srcport == 5802
   21 0.003839606    127.0.0.1 → 127.0.0.1    OsmoTRXD 196 Tx burst (L1 -> TRX): TDMA FN 0000631 TN 4, Modulation GMSK  udp.srcport == 5802
   22 0.003849782    127.0.0.1 → 127.0.0.1    OsmoTRXD 196 Tx burst (L1 -> TRX): TDMA FN 0000631 TN 5, Modulation GMSK  udp.srcport == 5802
   23 0.003860282    127.0.0.1 → 127.0.0.1    OsmoTRXD 196 Tx burst (L1 -> TRX): TDMA FN 0000631 TN 6, Modulation GMSK  udp.srcport == 5802
   24 0.003870536    127.0.0.1 → 127.0.0.1    OsmoTRXD 196 Tx burst (L1 -> TRX): TDMA FN 0000631 TN 7, Modulation GMSK  udp.srcport == 5802

# Normal bursts on C0 (dummy bursts are sent later)
   25 0.003882328    127.0.0.1 → 127.0.0.1    OsmoTRXD 196 Tx burst (L1 -> TRX): TDMA FN 0000632 TN 0, Modulation GMSK  udp.srcport == 5802
   26 0.003913169    127.0.0.1 → 127.0.0.1    OsmoTRXD 196 Tx burst (L1 -> TRX): TDMA FN 0000632 TN 3, Modulation GMSK  udp.srcport == 5802

# Dummy bursts on C0
   27 0.003930236    127.0.0.1 → 127.0.0.1    OsmoTRXD 196 Tx burst (L1 -> TRX): TDMA FN 0000632 TN 1, Modulation GMSK  udp.srcport == 5802
   28 0.003940799    127.0.0.1 → 127.0.0.1    OsmoTRXD 196 Tx burst (L1 -> TRX): TDMA FN 0000632 TN 2, Modulation GMSK  udp.srcport == 5802
   29 0.003950020    127.0.0.1 → 127.0.0.1    OsmoTRXD 196 Tx burst (L1 -> TRX): TDMA FN 0000632 TN 4, Modulation GMSK  udp.srcport == 5802
   30 0.003959976    127.0.0.1 → 127.0.0.1    OsmoTRXD 196 Tx burst (L1 -> TRX): TDMA FN 0000632 TN 5, Modulation GMSK  udp.srcport == 5802
   31 0.003969308    127.0.0.1 → 127.0.0.1    OsmoTRXD 196 Tx burst (L1 -> TRX): TDMA FN 0000632 TN 6, Modulation GMSK  udp.srcport == 5802
   32 0.003978739    127.0.0.1 → 127.0.0.1    OsmoTRXD 196 Tx burst (L1 -> TRX): TDMA FN 0000632 TN 7, Modulation GMSK  udp.srcport == 5802

# Normal bursts on C0 (dummy bursts are sent later)
   33 0.004605475    127.0.0.1 → 127.0.0.1    OsmoTRXD 196 Tx burst (L1 -> TRX): TDMA FN 0000633 TN 0, Modulation GMSK  udp.srcport == 5802
# A Normal burst on TRX2 (baseband freq. hopping)
   34 0.004623170    127.0.0.1 → 127.0.0.1    OsmoTRXD 196 Tx burst (L1 -> TRX): TDMA FN 0000633 TN 3, Modulation GMSK  udp.srcport == 5806

# Dummy bursts on C0
   35 0.004640723    127.0.0.1 → 127.0.0.1    OsmoTRXD 196 Tx burst (L1 -> TRX): TDMA FN 0000633 TN 1, Modulation GMSK  udp.srcport == 5802
   36 0.004651431    127.0.0.1 → 127.0.0.1    OsmoTRXD 196 Tx burst (L1 -> TRX): TDMA FN 0000633 TN 2, Modulation GMSK  udp.srcport == 5802
   37 0.004661183    127.0.0.1 → 127.0.0.1    OsmoTRXD 196 Tx burst (L1 -> TRX): TDMA FN 0000633 TN 3, Modulation GMSK  udp.srcport == 5802
   38 0.004671263    127.0.0.1 → 127.0.0.1    OsmoTRXD 196 Tx burst (L1 -> TRX): TDMA FN 0000633 TN 4, Modulation GMSK  udp.srcport == 5802
   39 0.004682597    127.0.0.1 → 127.0.0.1    OsmoTRXD 196 Tx burst (L1 -> TRX): TDMA FN 0000633 TN 5, Modulation GMSK  udp.srcport == 5802
   40 0.004695653    127.0.0.1 → 127.0.0.1    OsmoTRXD 196 Tx burst (L1 -> TRX): TDMA FN 0000633 TN 6, Modulation GMSK  udp.srcport == 5802
   41 0.004708738    127.0.0.1 → 127.0.0.1    OsmoTRXD 196 Tx burst (L1 -> TRX): TDMA FN 0000633 TN 7, Modulation GMSK  udp.srcport == 5802

# fake_trx.py forwards a burst with fn=631 (ok)
   42 0.004874924    127.0.0.1 → 127.0.0.1    OsmoTRXD 200 Rx burst (TRX -> L1): TDMA FN 0000631 TN 3  udp.srcport == 6702
# fake_trx.py forwards a burst with fn=633 (!)
   44 0.005565741    127.0.0.1 → 127.0.0.1    OsmoTRXD 200 Rx burst (TRX -> L1): TDMA FN 0000633 TN 3  udp.srcport == 6702
# fake_trx.py forwards a burst with fn=632 (!)
   47 0.008410835    127.0.0.1 → 127.0.0.1    OsmoTRXD 200 Rx burst (TRX -> L1): TDMA FN 0000632 TN 3  udp.srcport == 6702

and with some additional logging in fake_trx.py:

# Normal burst(s) on C0 (dummy bursts are sent later)
[DEBUG] transceiver.py:278 (BTS@127.0.0.1:5700) Rx burst: ver=1 fn=630 tn=0 bl=148 pwr=0

# fake_trx.py forwards a burst with fn=630 (ok)
[DEBUG] transceiver.py:278 (TRX2@127.0.0.1:5700/2) Rx burst: ver=1 fn=630 tn=3 bl=148 pwr=0
[DEBUG] fake_trx.py:256 (MS@127.0.0.1:6700) Tx burst: fn=630 tn=3 bl=148 rssi=-86 toa256=0

# Dummy bursts on C0
[DEBUG] transceiver.py:278 (BTS@127.0.0.1:5700) Rx burst: ver=1 fn=630 tn=1 bl=148 pwr=0
[DEBUG] transceiver.py:278 (BTS@127.0.0.1:5700) Rx burst: ver=1 fn=630 tn=2 bl=148 pwr=0
[DEBUG] transceiver.py:278 (BTS@127.0.0.1:5700) Rx burst: ver=1 fn=630 tn=3 bl=148 pwr=0
[DEBUG] transceiver.py:278 (BTS@127.0.0.1:5700) Rx burst: ver=1 fn=630 tn=4 bl=148 pwr=0
[DEBUG] transceiver.py:278 (BTS@127.0.0.1:5700) Rx burst: ver=1 fn=630 tn=5 bl=148 pwr=0
[DEBUG] transceiver.py:278 (BTS@127.0.0.1:5700) Rx burst: ver=1 fn=630 tn=6 bl=148 pwr=0
[DEBUG] transceiver.py:278 (BTS@127.0.0.1:5700) Rx burst: ver=1 fn=630 tn=7 bl=148 pwr=0

# Normal burst(s) on C0 (dummy bursts are sent later)
[DEBUG] transceiver.py:278 (BTS@127.0.0.1:5700) Rx burst: ver=1 fn=631 tn=0 bl=148 pwr=0

# fake_trx.py forwards a burst with fn=631 (ok)
[DEBUG] transceiver.py:278 (TRX3@127.0.0.1:5700/3) Rx burst: ver=1 fn=631 tn=3 bl=148 pwr=0
[DEBUG] fake_trx.py:256 (MS@127.0.0.1:6700) Tx burst: fn=631 tn=3 bl=148 rssi=-86 toa256=0

# Dummy burst(s) on C0
[DEBUG] transceiver.py:278 (BTS@127.0.0.1:5700) Rx burst: ver=1 fn=631 tn=1 bl=148 pwr=0

# fake_trx.py forwards a burst with fn=633 (!)
[DEBUG] transceiver.py:278 (TRX2@127.0.0.1:5700/2) Rx burst: ver=1 fn=633 tn=3 bl=148 pwr=0
[DEBUG] fake_trx.py:256 (MS@127.0.0.1:6700) Tx burst: fn=633 tn=3 bl=148 rssi=-86 toa256=0

# Dummy burst(s) on C0
[DEBUG] transceiver.py:278 (BTS@127.0.0.1:5700) Rx burst: ver=1 fn=631 tn=2 bl=148 pwr=0
[DEBUG] transceiver.py:278 (BTS@127.0.0.1:5700) Rx burst: ver=1 fn=631 tn=3 bl=148 pwr=0
[DEBUG] transceiver.py:278 (BTS@127.0.0.1:5700) Rx burst: ver=1 fn=631 tn=4 bl=148 pwr=0
[DEBUG] transceiver.py:278 (BTS@127.0.0.1:5700) Rx burst: ver=1 fn=631 tn=5 bl=148 pwr=0
[DEBUG] transceiver.py:278 (BTS@127.0.0.1:5700) Rx burst: ver=1 fn=631 tn=6 bl=148 pwr=0
[DEBUG] transceiver.py:278 (BTS@127.0.0.1:5700) Rx burst: ver=1 fn=631 tn=7 bl=148 pwr=0

# fake_trx.py forwards a burst with fn=632 (!)
[DEBUG] transceiver.py:278 (BTS@127.0.0.1:5700) Rx burst: ver=1 fn=632 tn=3 bl=148 pwr=0
[DEBUG] fake_trx.py:256 (MS@127.0.0.1:6700) Tx burst: fn=632 tn=3 bl=148 rssi=-86 toa256=0

The problem is that unlike osmo-trx, fake_trx.py does not queue bursts before forwarding them. This means that all incoming bursts get passed through immediately as soon as they're received. I know that UDP does not guarantee packet sequencing, but this is not so important. Regardless of that, we deal with multiple UDP connections in a select() loop, so packet sequencing on the transport layer would not help much. There is always a chance of a race condition between the parallel TRXD connections.

#4 Updated by fixeria 26 days ago

If last processed FN is higher than the one received, increment counter, log error and don't enqueue it.

https://gerrit.osmocom.org/c/osmocom-bb/+/19201 trxcon/scheduler: check TDMA frame order, drop out of order bursts

#5 Updated by fixeria 26 days ago

When enqueueing, make sure it is included in the correct place in the linked list of the queue, so that content is always sorted by FN.

This sounds interesting, but a) it may happen that the difference between fn1 and fn2 would be more than 1 TDMA frame, so we would need to maintain larger burst buffers and the measurement history; b) we somehow need to compensate lost bursts, and this decision needs to be made quick enough.

The problem is that unlike osmo-trx, fake_trx.py does not queue bursts before forwarding them.

I am afraid the proper way is to implement burst queuing (buffering) in fake_trx.py. This would make it more CPU hungry.

Any (more) suggestions and ideas are welcome!

#6 Updated by fixeria 26 days ago

  • Status changed from New to In Progress
  • % Done changed from 0 to 20

#7 Updated by fixeria 22 days ago

  • Status changed from In Progress to Feedback
  • % Done changed from 20 to 90

Should be fixed by:

https://gerrit.osmocom.org/c/osmocom-bb/+/19228 trx_toolkit/transceiver.py: implement the transmit burst queue

at least I don't see the out of order bursts in trxcon anymore. Waiting for code review.

#8 Updated by fixeria 22 days ago

The following test cases from ttcn3-bts-test started to fail (tested in Docker) with this change applied:

  • pass->FAIL BTS_Tests.TC_rsl_ms_pwr_ctrl
  • pass->FAIL BTS_Tests.TC_rsl_ms_pwr_dyn_up
  • pass->FAIL BTS_Tests.TC_rsl_ms_pwr_dyn_ass_updown
  • pass->FAIL BTS_Tests.TC_paging_imsi_200percent
  • pass->FAIL BTS_Tests.TC_paging_tmsi_200percent
  • pass->FAIL BTS_Tests.TC_pcu_time_ind
  • pass->FAIL BTS_Tests.TC_pcu_rts_req
  • pass->FAIL BTS_Tests_SMSCB.TC_sms_cb_cmd_sdcch4_1block
  • pass->FAIL BTS_Tests_SMSCB.TC_sms_cb_cmd_sdcch4_2block
  • pass->FAIL BTS_Tests_SMSCB.TC_sms_cb_cmd_sdcch4_3block
  • pass->FAIL BTS_Tests_SMSCB.TC_sms_cb_cmd_sdcch4_4block
  • pass->FAIL BTS_Tests_SMSCB.TC_sms_cb_cmd_sdcch4_multi
  • pass->FAIL BTS_Tests_SMSCB.TC_sms_cb_cmd_sdcch4_schedule
  • pass->FAIL BTS_Tests_SMSCB.TC_sms_cb_cmd_sdcch4_default_and_normal
  • pass->FAIL BTS_Tests_SMSCB.TC_cbc_sdcch4_load_overload
  • pass->FAIL BTS_Tests_LAPDm.TC_iframe_seq_and_ack
  • pass->FAIL BTS_Tests_LAPDm.TC_rec_invalid_frame (this one is actually quite sporadic)
  • pass->FAIL BTS_Tests_LAPDm.TC_segm_concat_sacch

I kind of expected that, since we're still using fn-advance=20 (!) in both osmo-bts-trx and trxcon by default (see #4487).

#9 Updated by fixeria 19 days ago

  • Status changed from Feedback to Resolved
  • % Done changed from 90 to 100

All changes have been merged, the problem is solved.

The following test cases from ttcn3-bts-test started to fail (tested in Docker) with this change applied:

I'll create a separate ticket.

#10 Updated by fixeria 18 days ago

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

Unfortunately, Python is not fast enough to handle the queues in time. Despite the relatively low CPU usage, fake_trx.py fails to scheduler everything during one TDMA frame period. This causes some of our TTCN-3 test cases to fail. Sigh :/

Here is what I see in the log output of osmo-bts-trx:

20200715113418508 DL1C <0006> scheduler_trx.c:322 GSM clock jitter: -42697us (elapsed_fn=-9)
20200715113418508 DL1C <0006> scheduler_trx.c:331 We were 9 FN faster than TRX, compensating
20200715113419016 DL1C <0006> scheduler_trx.c:322 GSM clock jitter: -37369us (elapsed_fn=-7)
20200715113419016 DL1C <0006> scheduler_trx.c:331 We were 7 FN faster than TRX, compensating
20200715113419528 DL1C <0006> scheduler_trx.c:322 GSM clock jitter: -40270us (elapsed_fn=-8)
20200715113419528 DL1C <0006> scheduler_trx.c:331 We were 8 FN faster than TRX, compensating
20200715113420040 DL1C <0006> scheduler_trx.c:322 GSM clock jitter: -41157us (elapsed_fn=-8)
20200715113420040 DL1C <0006> scheduler_trx.c:331 We were 8 FN faster than TRX, compensating
20200715113420549 DL1C <0006> scheduler_trx.c:322 GSM clock jitter: -38258us (elapsed_fn=-8)
20200715113420549 DL1C <0006> scheduler_trx.c:331 We were 8 FN faster than TRX, compensating
20200715113421061 DL1C <0006> scheduler_trx.c:322 GSM clock jitter: -40767us (elapsed_fn=-8)
20200715113421061 DL1C <0006> scheduler_trx.c:331 We were 8 FN faster than TRX, compensating
20200715113421574 DL1C <0006> scheduler_trx.c:322 GSM clock jitter: -42539us (elapsed_fn=-9)
20200715113421574 DL1C <0006> scheduler_trx.c:331 We were 9 FN faster than TRX, compensating
20200715113422091 DL1C <0006> scheduler_trx.c:322 GSM clock jitter: -45894us (elapsed_fn=-9)
20200715113422091 DL1C <0006> scheduler_trx.c:331 We were 9 FN faster than TRX, compensating
20200715113422607 DL1C <0006> scheduler_trx.c:322 GSM clock jitter: -44628us (elapsed_fn=-9)
20200715113422607 DL1C <0006> scheduler_trx.c:331 We were 9 FN faster than TRX, compensating
20200715113423110 DL1C <0006> scheduler_trx.c:322 GSM clock jitter: -31977us (elapsed_fn=-6)
20200715113423110 DL1C <0006> scheduler_trx.c:331 We were 6 FN faster than TRX, compensating
20200715113423626 DL1C <0006> scheduler_trx.c:322 GSM clock jitter: -45440us (elapsed_fn=-9)
20200715113423626 DL1C <0006> scheduler_trx.c:331 We were 9 FN faster than TRX, compensating

...

20200715113453055 DL1C <0006> scheduler_trx.c:322 GSM clock jitter: -144201us (elapsed_fn=-31)
20200715113453055 DL1C <0006> scheduler_trx.c:331 We were 31 FN faster than TRX, compensating
20200715113453682 DL1C <0006> scheduler_trx.c:322 GSM clock jitter: -156103us (elapsed_fn=-33)
20200715113453682 DL1C <0006> scheduler_trx.c:331 We were 33 FN faster than TRX, compensating
20200715113454300 DL1C <0006> scheduler_trx.c:322 GSM clock jitter: -147080us (elapsed_fn=-31)
20200715113454300 DL1C <0006> scheduler_trx.c:331 We were 31 FN faster than TRX, compensating
20200715113454921 DL1C <0006> scheduler_trx.c:322 GSM clock jitter: -150501us (elapsed_fn=-32)
20200715113454921 DL1C <0006> scheduler_trx.c:331 We were 32 FN faster than TRX, compensating
20200715113455548 DL1C <0006> scheduler_trx.c:322 GSM clock jitter: -155247us (elapsed_fn=-33)
20200715113455548 DL1C <0006> scheduler_trx.c:331 We were 33 FN faster than TRX, compensating
20200715113456174 DL1C <0006> scheduler_trx.c:322 GSM clock jitter: -155124us (elapsed_fn=-33)
20200715113456174 DL1C <0006> scheduler_trx.c:331 We were 33 FN faster than TRX, compensating
20200715113456789 DL1C <0006> scheduler_trx.c:322 GSM clock jitter: -144262us (elapsed_fn=-31)
20200715113456789 DL1C <0006> scheduler_trx.c:331 We were 31 FN faster than TRX, compensating
20200715113457400 DL1C <0006> scheduler_trx.c:322 GSM clock jitter: -140592us (elapsed_fn=-30)
20200715113457400 DL1C <0006> scheduler_trx.c:331 We were 30 FN faster than TRX, compensating
20200715113457976 DL1C <0006> scheduler_trx.c:322 GSM clock jitter: -104447us (elapsed_fn=-22)
20200715113457976 DL1C <0006> scheduler_trx.c:331 We were 22 FN faster than TRX, compensating
20200715113458588 DL1C <0006> scheduler_trx.c:322 GSM clock jitter: -141266us (elapsed_fn=-30)

Most likely, the problem is that Python's threading.Event is not accurate enough. Running with SCHED_RR does not change anything.

Also available in: Atom PDF

Add picture from clipboard (Maximum size: 48.8 MB)