Project

General

Profile

Actions

Bug #6200

open

osmo-trx-ms: lots of @Received bad frame (rc=-1, ber=444/444)@

Added by fixeria 5 months ago. Updated 5 months ago.

Status:
New
Priority:
High
Assignee:
Category:
-
Target version:
Start date:
10/03/2023
Due date:
% Done:

0%

Resolution:
Spec Reference:
Tags:

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

Related to OsmocomBB - Bug #6342: ms-sdr gprs performanceFeedbackHoernchen01/24/2024

Actions
Blocked by OsmocomBB - Bug #6206: modem: "UL_TBF_ASS[0x5570b55bf0]{IDLE}: Event CREATE_RLCMAC_MSG not permitted"Resolvedfixeria10/05/2023

Actions
Actions #1

Updated by fixeria 5 months ago

  • Blocked by Bug #6206: modem: "UL_TBF_ASS[0x5570b55bf0]{IDLE}: Event CREATE_RLCMAC_MSG not permitted" added
Actions #2

Updated by fixeria 5 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?

Actions #3

Updated by fixeria 5 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 #4

Updated by Hoernchen 26 days ago

  • Related to Bug #6342: ms-sdr gprs performance added
Actions

Also available in: Atom PDF

Add picture from clipboard (Maximum size: 48.8 MB)