Dear Jacob,
Finally I managed to get everything in a working order, so I can finally start testing the GPRS part of OpenBSC/Osmo-PCU with an USRP B200.
I am using a Cat 12 device with a 4 PDCH configuration.
In the past I wrote a little script to test the PRACH stability of OpenBTS, which sends a single ping to the gateway address, waits until the session goes into idle, and then tries again. The goal is to generate as many PRACH as possible and check if there is a response.
I used this script and it turns out that around 1 out of every 20 requests the ping is not reaching the gateway, and the UE indicates an abnormal DL TBF release.
I attached the UE side log, so you can take a look.
During this issue there is no reasonable frequency nor timing variation indicated on the UE side.
What I noticed is the very high number of RLC resent and RLC restarted. After a few minutes of pinging, this is the result from the PCU:
RLC Sent : 18015 (0/s 0/m 0/h 0/d) RLC Resent : 17596 (0/s 0/m 0/h 0/d) RLC Restarted : 15669 (0/s 0/m 0/h 0/d) RLC Stalled : 0 (0/s 0/m 0/h 0/d)
Please note that the ARFCN I use is completely clean, I filter the uplink with proper duplexer and the TRX is not complaining about anything.
Also interesting that during constant pinging (the system does not need to do PRACH), this problem is not popping up.
Will update my UHD stack from 3.8.0 to 3.9.0 just to test with the latest, but I don't think itt will change anything about this issue. And to be hones, we've seen similar PRACH related issues with OpenBTS GPRS too.
If you need any more logs or you have an idea what to try, I am happy to do that. :-)
Regards, Csaba
On 20 Sep 2015, at 21:15, Sipos Csaba sipos.csaba@kvk.uni-obuda.hu wrote:
Dear Jacob,
Finally I managed to get everything in a working order, so I can finally start testing the GPRS part of OpenBSC/Osmo-PCU with an USRP B200.
I am using a Cat 12 device with a 4 PDCH configuration.
I attached the UE side log, so you can take a look.
How did you get these logs?
Dear Csaba,
which exact PCU version (git SHA stamp) are you using?
On 20.09.2015 21:15, Sipos Csaba wrote:
In the past I wrote a little script to test the PRACH stability of OpenBTS, which sends a single ping to the gateway address, waits until the session goes into idle, and then tries again. The goal is to generate as many PRACH as possible and check if there is a response.
I used this script and it turns out that around 1 out of every 20 requests the ping is not reaching the gateway, and the UE indicates an abnormal DL TBF release.
I attached the UE side log, so you can take a look.
The UE side log doesn't help much, as I cannot see much differences between either case (even the time deltas before each EVENT_GPRS_TBF_RELEASE are similar). It would be very helpful, if I had the logging output of the PCU, e.g. by adding the following stanza to the osmo-pcu.cfg file:
==== log file /tmp/pcu.log logging filter all 1 logging color 0 logging print extended-timestamp 1 logging level all everything logging level rlcmac debug logging level rlcmacul debug logging level rlcmacdl debug logging level l1if info logging level bssgp debug logging level rlcmacdata debug logging level rlcmacmeas debug logging level rlcmacsched debug logging level pcu debug ====
During this issue there is no reasonable frequency nor timing variation indicated on the UE side.
What I noticed is the very high number of RLC resent and RLC restarted. After a few minutes of pinging, this is the result from the PCU:
RLC Sent : 18015 (0/s 0/m 0/h 0/d) RLC Resent : 17596 (0/s 0/m 0/h 0/d) RLC Restarted : 15669 (0/s 0/m 0/h 0/d) RLC Stalled : 0 (0/s 0/m 0/h 0/d)
This probably results from the dl-tbf-idle-time feature. When enabled, the DL TBF is not closed after the last LLC frame. Instead the DL TBF is kept open by sending LLC dummy commands at regular intervals. Each of them creates a single RLC packet which is then resent in every free slot with a low priority until the corresponding ACK is received. Note that this rewrapping of the send buffer will not happen, when there is other data to be sent (this is meant by 'low priority').
Regards
Jacob
Dear Jacob,
I am using the laster master branch of Osmo-PCU. Last commit:
commit 7c8d39a67b7568cda38829c774ea541250f3142f Author: Jacob Erlbeck jerlbeck@sysmocom.de Date: Mon Sep 7 14:04:56 2015 +0200
poll: Count failed procedures
The UE side log doesn't help much
After I gone through it the second time, thats what I tought too :-)
I added the extra log options to the pcu config and now try to reproduce the error. Will try and give you as much details as possible.
Regards, Csaba
----- Eredeti üzenet ----- Feladó: "Jacob Erlbeck" jerlbeck@sysmocom.de Címzett: "Sipos Csaba" sipos.csaba@kvk.uni-obuda.hu Másolatot kap: "OpenBSC Mailing List" openbsc@lists.osmocom.org Elküldött üzenetek: Hétfő, 2015. Szeptember 21. 12:30:31 Tárgy: Re: DL TBF abnormal release
Dear Csaba,
which exact PCU version (git SHA stamp) are you using?
On 20.09.2015 21:15, Sipos Csaba wrote:
In the past I wrote a little script to test the PRACH stability of OpenBTS, which sends a single ping to the gateway address, waits until the session goes into idle, and then tries again. The goal is to generate as many PRACH as possible and check if there is a response.
I used this script and it turns out that around 1 out of every 20 requests the ping is not reaching the gateway, and the UE indicates an abnormal DL TBF release.
I attached the UE side log, so you can take a look.
The UE side log doesn't help much, as I cannot see much differences between either case (even the time deltas before each EVENT_GPRS_TBF_RELEASE are similar). It would be very helpful, if I had the logging output of the PCU, e.g. by adding the following stanza to the osmo-pcu.cfg file:
==== log file /tmp/pcu.log logging filter all 1 logging color 0 logging print extended-timestamp 1 logging level all everything logging level rlcmac debug logging level rlcmacul debug logging level rlcmacdl debug logging level l1if info logging level bssgp debug logging level rlcmacdata debug logging level rlcmacmeas debug logging level rlcmacsched debug logging level pcu debug ====
During this issue there is no reasonable frequency nor timing variation indicated on the UE side.
What I noticed is the very high number of RLC resent and RLC restarted. After a few minutes of pinging, this is the result from the PCU:
RLC Sent : 18015 (0/s 0/m 0/h 0/d) RLC Resent : 17596 (0/s 0/m 0/h 0/d) RLC Restarted : 15669 (0/s 0/m 0/h 0/d) RLC Stalled : 0 (0/s 0/m 0/h 0/d)
This probably results from the dl-tbf-idle-time feature. When enabled, the DL TBF is not closed after the last LLC frame. Instead the DL TBF is kept open by sending LLC dummy commands at regular intervals. Each of them creates a single RLC packet which is then resent in every free slot with a low priority until the corresponding ACK is received. Note that this rewrapping of the send buffer will not happen, when there is other data to be sent (this is meant by 'low priority').
Regards
Jacob
Dear Jacob,
I run my PRACH test for a few minutes and the problem popped up. I am attahcing the UE and the PCU side logs.
In the UE log note that the UL TBF is released almost right after the PRACH is finsihed, while the ICMP echo request is being sent (and lost).
In the PCU log the interesting part is close to the bottom. One line to highlight:
Software error: Pending downlink assignment. This may not happen, because the assignment message never gets transmitted. Please be sure not to free in this state. PLEASE FIX!
This message is quite close to the part where the ICMP echo request got lost, but it is hard to tell because to two logs are not synchronised.
Will continue testing because this error looks a littlebit different than the one I catched yesterday.
Regards, Csaba
----- Eredeti üzenet ----- Feladó: "Sipos Csaba" sipos.csaba@kvk.uni-obuda.hu Címzett: "Jacob Erlbeck" jerlbeck@sysmocom.de Másolatot kap: "OpenBSC Mailing List" openbsc@lists.osmocom.org Elküldött üzenetek: Hétfő, 2015. Szeptember 21. 21:10:16 Tárgy: Re: DL TBF abnormal release
Dear Jacob,
I am using the laster master branch of Osmo-PCU. Last commit:
commit 7c8d39a67b7568cda38829c774ea541250f3142f Author: Jacob Erlbeck jerlbeck@sysmocom.de Date: Mon Sep 7 14:04:56 2015 +0200
poll: Count failed procedures
The UE side log doesn't help much
After I gone through it the second time, thats what I tought too :-)
I added the extra log options to the pcu config and now try to reproduce the error. Will try and give you as much details as possible.
Regards, Csaba
----- Eredeti üzenet ----- Feladó: "Jacob Erlbeck" jerlbeck@sysmocom.de Címzett: "Sipos Csaba" sipos.csaba@kvk.uni-obuda.hu Másolatot kap: "OpenBSC Mailing List" openbsc@lists.osmocom.org Elküldött üzenetek: Hétfő, 2015. Szeptember 21. 12:30:31 Tárgy: Re: DL TBF abnormal release
Dear Csaba,
which exact PCU version (git SHA stamp) are you using?
On 20.09.2015 21:15, Sipos Csaba wrote:
In the past I wrote a little script to test the PRACH stability of OpenBTS, which sends a single ping to the gateway address, waits until the session goes into idle, and then tries again. The goal is to generate as many PRACH as possible and check if there is a response.
I used this script and it turns out that around 1 out of every 20 requests the ping is not reaching the gateway, and the UE indicates an abnormal DL TBF release.
I attached the UE side log, so you can take a look.
The UE side log doesn't help much, as I cannot see much differences between either case (even the time deltas before each EVENT_GPRS_TBF_RELEASE are similar). It would be very helpful, if I had the logging output of the PCU, e.g. by adding the following stanza to the osmo-pcu.cfg file:
==== log file /tmp/pcu.log logging filter all 1 logging color 0 logging print extended-timestamp 1 logging level all everything logging level rlcmac debug logging level rlcmacul debug logging level rlcmacdl debug logging level l1if info logging level bssgp debug logging level rlcmacdata debug logging level rlcmacmeas debug logging level rlcmacsched debug logging level pcu debug ====
During this issue there is no reasonable frequency nor timing variation indicated on the UE side.
What I noticed is the very high number of RLC resent and RLC restarted. After a few minutes of pinging, this is the result from the PCU:
RLC Sent : 18015 (0/s 0/m 0/h 0/d) RLC Resent : 17596 (0/s 0/m 0/h 0/d) RLC Restarted : 15669 (0/s 0/m 0/h 0/d) RLC Stalled : 0 (0/s 0/m 0/h 0/d)
This probably results from the dl-tbf-idle-time feature. When enabled, the DL TBF is not closed after the last LLC frame. Instead the DL TBF is kept open by sending LLC dummy commands at regular intervals. Each of them creates a single RLC packet which is then resent in every free slot with a low priority until the corresponding ACK is received. Note that this rewrapping of the send buffer will not happen, when there is other data to be sent (this is meant by 'low priority').
Regards
Jacob
-
Holger Freyther -
Jacob Erlbeck -
Sipos Csaba