Actions
Bug #6200
openosmo-trx-ms: lots of @Received bad frame (rc=-1, ber=444/444)@
Start date:
10/03/2023
Due date:
% Done:
0%
Resolution:
Spec Reference:
Description
Hi Hoernchen,
we had a debugging session with pespin today and we got the mssdr-ms side to work more or less reliably. But we noticed a weird problem:
20231003152951965 DL1C NOTICE trxcon(0)[0x5579a42900]{BCCH_CCCH}: L1CTL_DM_EST_REQ indicates single ARFCN GSM900 979 (l1ctl.c:572)
20231003152951965 DSCH NOTICE trxcon(0)[0x5579a42900]: Reset scheduler (sched_trx.c:190)
20231003152951965 DSCH NOTICE trxcon(0)[0x5579a42900]: Delete TDMA timeslot #0 (sched_trx.c:226)
20231003152951965 DSCH NOTICE trxcon(0)[0x5579a42900]: Add a new TDMA timeslot #4 (sched_trx.c:207)
20231003152951965 DSCH NOTICE trxcon(0)[0x5579a42900]: (Re)configure TDMA timeslot #4 as PDCH (sched_trx.c:276)
20231003152951966 DSCH NOTICE trxcon(0)[0x5579a42900]: TS4-PDTCH activating (sched_trx.c:476)
20231003152951966 DSCH NOTICE trxcon(0)[0x5579a42900]: TS4-PTCCH activating (sched_trx.c:476)
20231003152953364 DSCHD ERROR trxcon(0)[0x5579a42900]: TS4-PDTCH Received bad frame (rc=-1, ber=86/456) at fn=513573 (sched_lchan_pdtch.c:94)
20231003152954366 DSCHD ERROR trxcon(0)[0x5579a42900]: TS4-PDTCH Received bad frame (rc=-1, ber=87/456) at fn=513790 (sched_lchan_pdtch.c:94)
20231003152954804 DSCHD ERROR trxcon(0)[0x5579a42900]: TS4-PDTCH Received bad frame (rc=-1, ber=444/444) at fn=513885 (sched_lchan_pdtch.c:94)
20231003152954827 DSCHD ERROR trxcon(0)[0x5579a42900]: TS4-PDTCH Received bad frame (rc=-1, ber=444/444) at fn=513890 (sched_lchan_pdtch.c:94)
20231003152954846 DSCHD ERROR trxcon(0)[0x5579a42900]: TS4-PDTCH Received bad frame (rc=-1, ber=444/444) at fn=513894 (sched_lchan_pdtch.c:94)
20231003152954864 DSCHD ERROR trxcon(0)[0x5579a42900]: TS4-PDTCH Received bad frame (rc=-1, ber=444/444) at fn=513898 (sched_lchan_pdtch.c:94)
20231003152954887 DSCHD ERROR trxcon(0)[0x5579a42900]: TS4-PDTCH Received bad frame (rc=-1, ber=444/444) at fn=513903 (sched_lchan_pdtch.c:94)
20231003152954906 DSCHD ERROR trxcon(0)[0x5579a42900]: TS4-PDTCH Received bad frame (rc=-1, ber=444/444) at fn=513907 (sched_lchan_pdtch.c:94)
20231003152954924 DSCHD ERROR trxcon(0)[0x5579a42900]: TS4-PDTCH Received bad frame (rc=-1, ber=444/444) at fn=513911 (sched_lchan_pdtch.c:94)
20231003152954947 DSCHD ERROR trxcon(0)[0x5579a42900]: TS4-PDTCH Received bad frame (rc=-1, ber=444/444) at fn=513916 (sched_lchan_pdtch.c:94)
20231003152954966 DSCHD ERROR trxcon(0)[0x5579a42900]: TS4-PDTCH Received bad frame (rc=-1, ber=444/444) at fn=513920 (sched_lchan_pdtch.c:94)
20231003152954984 DSCHD ERROR trxcon(0)[0x5579a42900]: TS4-PDTCH Received bad frame (rc=-1, ber=444/444) at fn=513924 (sched_lchan_pdtch.c:94)
20231003152955007 DSCHD ERROR trxcon(0)[0x5579a42900]: TS4-PDTCH Received bad frame (rc=-1, ber=444/444) at fn=513929 (sched_lchan_pdtch.c:94)
20231003152955025 DSCHD ERROR trxcon(0)[0x5579a42900]: TS4-PDTCH Received bad frame (rc=-1, ber=444/444) at fn=513933 (sched_lchan_pdtch.c:94)
20231003152955044 DSCHD ERROR trxcon(0)[0x5579a42900]: TS4-PDTCH Received bad frame (rc=-1, ber=444/444) at fn=513937 (sched_lchan_pdtch.c:94)
20231003152955067 DSCHD ERROR trxcon(0)[0x5579a42900]: TS4-PDTCH Received bad frame (rc=-1, ber=444/444) at fn=513942 (sched_lchan_pdtch.c:94)
20231003152955085 DSCHD ERROR trxcon(0)[0x5579a42900]: TS4-PDTCH Received bad frame (rc=-1, ber=444/444) at fn=513946 (sched_lchan_pdtch.c:94)
20231003152955104 DSCHD ERROR trxcon(0)[0x5579a42900]: TS4-PDTCH Received bad frame (rc=-1, ber=444/444) at fn=513950 (sched_lchan_pdtch.c:94)
20231003152955127 DSCHD ERROR trxcon(0)[0x5579a42900]: TS4-PDTCH Received bad frame (rc=-1, ber=444/444) at fn=513955 (sched_lchan_pdtch.c:94)
20231003152955145 DSCHD ERROR trxcon(0)[0x5579a42900]: TS4-PDTCH Received bad frame (rc=-1, ber=444/444) at fn=513959 (sched_lchan_pdtch.c:94)
20231003152955164 DSCHD ERROR trxcon(0)[0x5579a42900]: TS4-PDTCH Received bad frame (rc=-1, ber=444/444) at fn=513963 (sched_lchan_pdtch.c:94)
20231003152955188 DSCHD ERROR trxcon(0)[0x5579a42900]: TS4-PDTCH Received bad frame (rc=-1, ber=444/444) at fn=513968 (sched_lchan_pdtch.c:94)
20231003152955205 DSCHD ERROR trxcon(0)[0x5579a42900]: TS4-PDTCH Received bad frame (rc=-1, ber=444/444) at fn=513972 (sched_lchan_pdtch.c:94)
20231003152955224 DSCHD ERROR trxcon(0)[0x5579a42900]: TS4-PDTCH Received bad frame (rc=-1, ber=444/444) at fn=513976 (sched_lchan_pdtch.c:94)
20231003152955248 DSCHD ERROR trxcon(0)[0x5579a42900]: TS4-PDTCH Received bad frame (rc=-1, ber=444/444) at fn=513981 (sched_lchan_pdtch.c:94)
20231003152955265 DSCHD ERROR trxcon(0)[0x5579a42900]: TS4-PDTCH Received bad frame (rc=-1, ber=444/444) at fn=513985 (sched_lchan_pdtch.c:94)
20231003152955284 DSCHD ERROR trxcon(0)[0x5579a42900]: TS4-PDTCH Received bad frame (rc=-1, ber=444/444) at fn=513989 (sched_lchan_pdtch.c:94)
20231003152955308 DSCHD ERROR trxcon(0)[0x5579a42900]: TS4-PDTCH Received bad frame (rc=-1, ber=444/444) at fn=513994 (sched_lchan_pdtch.c:94)
20231003152955325 DSCHD ERROR trxcon(0)[0x5579a42900]: TS4-PDTCH Received bad frame (rc=-1, ber=444/444) at fn=513998 (sched_lchan_pdtch.c:94)
20231003152955344 DSCHD ERROR trxcon(0)[0x5579a42900]: TS4-PDTCH Received bad frame (rc=-1, ber=444/444) at fn=514002 (sched_lchan_pdtch.c:94)
20231003152955368 DSCHD ERROR trxcon(0)[0x5579a42900]: TS4-PDTCH Received bad frame (rc=-1, ber=444/444) at fn=514007 (sched_lchan_pdtch.c:94)
20231003152955385 DSCHD ERROR trxcon(0)[0x5579a42900]: TS4-PDTCH Received bad frame (rc=-1, ber=444/444) at fn=514011 (sched_lchan_pdtch.c:94)
20231003152955404 DSCHD ERROR trxcon(0)[0x5579a42900]: TS4-PDTCH Received bad frame (rc=-1, ber=444/444) at fn=514015 (sched_lchan_pdtch.c:94)
It's not seen during the GMM ATTACH and SM PDP CTX ACT procedures, but only when we tried sending some data (ICMP ping) over the tun interface.
As can be seen, quite a lot of Downlink PDCH blocks not being decoded. The BER=444/444 makes me think that received bursts were all 0 (neither -127 nor 127).
This is enlarging the ping delays significantly (from ~600ms to ~5000ms ==> ~10 times):
PING 176.16.222.1 (176.16.222.1) 56(84) bytes of data. 64 bytes from 176.16.222.1: icmp_seq=1 ttl=64 time=681 ms 64 bytes from 176.16.222.1: icmp_seq=2 ttl=64 time=803 ms 64 bytes from 176.16.222.1: icmp_seq=3 ttl=64 time=625 ms 64 bytes from 176.16.222.1: icmp_seq=4 ttl=64 time=525 ms 64 bytes from 176.16.222.1: icmp_seq=5 ttl=64 time=5646 ms 64 bytes from 176.16.222.1: icmp_seq=6 ttl=64 time=4678 ms 64 bytes from 176.16.222.1: icmp_seq=7 ttl=64 time=3911 ms 64 bytes from 176.16.222.1: icmp_seq=8 ttl=64 time=2948 ms 64 bytes from 176.16.222.1: icmp_seq=9 ttl=64 time=1984 ms 64 bytes from 176.16.222.1: icmp_seq=10 ttl=64 time=1020 ms 64 bytes from 176.16.222.1: icmp_seq=11 ttl=64 time=602 ms 64 bytes from 176.16.222.1: icmp_seq=12 ttl=64 time=742 ms 64 bytes from 176.16.222.1: icmp_seq=13 ttl=64 time=5741 ms 64 bytes from 176.16.222.1: icmp_seq=14 ttl=64 time=4769 ms 64 bytes from 176.16.222.1: icmp_seq=15 ttl=64 time=3824 ms 64 bytes from 176.16.222.1: icmp_seq=16 ttl=64 time=2860 ms 64 bytes from 176.16.222.1: icmp_seq=17 ttl=64 time=1896 ms 64 bytes from 176.16.222.1: icmp_seq=18 ttl=64 time=932 ms 64 bytes from 176.16.222.1: icmp_seq=19 ttl=64 time=813 ms 64 bytes from 176.16.222.1: icmp_seq=20 ttl=64 time=653 ms 64 bytes from 176.16.222.1: icmp_seq=21 ttl=64 time=5630 ms 64 bytes from 176.16.222.1: icmp_seq=22 ttl=64 time=4658 ms 64 bytes from 176.16.222.1: icmp_seq=23 ttl=64 time=3893 ms 64 bytes from 176.16.222.1: icmp_seq=24 ttl=64 time=2929 ms 64 bytes from 176.16.222.1: icmp_seq=25 ttl=64 time=1969 ms 64 bytes from 176.16.222.1: icmp_seq=26 ttl=64 time=1005 ms 64 bytes from 176.16.222.1: icmp_seq=27 ttl=64 time=546 ms 64 bytes from 176.16.222.1: icmp_seq=28 ttl=64 time=686 ms
This looks like a PHY problem to me, so assigning to you.
Related issues
Updated by fixeria 7 months ago
I can confirm that the errors are related to the PDCH power saving feature: if I turn it off by patching osmo-pcu, I see no more errors like above.
But it should be noted that some Downlink PDCH blocks are still being not decoded due to errors, e.g.:
20231005150808509 DSCHD ERROR trxcon(0)[0x55ac809900]: TS3-PDTCH Received bad frame (rc=-1, ber=98/456) at fn=2367430 (sched_lchan_pdtch.c:94)
I am also seeing sporadic BCCH/SCH decoding errors:
20231005151114641 DSCHD ERROR trxcon(0)[0x55ac809900]: TS0-SCH Received bad SCH burst at fn=2407762 (sched_lchan_sch.c:96) 20231005151114660 DSCHD ERROR trxcon(0)[0x55ac809900]: TS0-BCCH Received bad frame (rc=-1, ber=343/456) at fn=2407763 (sched_lchan_xcch.c:94)
It's a lab setup with nearly perfect RF conditions, so I am assuming this shall not happen at all?
Updated by fixeria 7 months ago
- Priority changed from Normal to High
fixeria wrote in #note-2:
I can confirm that the errors are related to the PDCH power saving feature: if I turn it off by patching osmo-pcu, I see no more errors like above.
Ignore this. Now I am also seeing these errors even with the power saving feature disabled. Try ping'ing the MS from the BTS side and you'll see them.
Actions
