diff options
author | Jacob Erlbeck <jerlbeck@sysmocom.de> | 2015-08-24 13:30:39 +0200 |
---|---|---|
committer | Jacob Erlbeck <jerlbeck@sysmocom.de> | 2015-08-28 12:23:07 +0200 |
commit | 16d29c7da4ee516b4ef0a6ec18cec18f8a76d7fa (patch) | |
tree | 79313a803e7be5994e02fce7bd61e34c64f9f3fa | |
parent | b6b3c7eb2727da98fbba231d9a1e9fe4a33b2dd0 (diff) |
tbf: Add logging for polling
This commit adds the relevant frame number to the "poll timeout"
logging message. In addition, logging is added to the places where
poll_fn gets set.
The goal is to track down the source for frequent "poll timeout"
messages.
Sponsored-by: On-Waves ehf
-rw-r--r-- | src/tbf.cpp | 10 | ||||
-rw-r--r-- | src/tbf_dl.cpp | 4 | ||||
-rw-r--r-- | tests/tbf/TbfTest.err | 16 |
3 files changed, 28 insertions, 2 deletions
diff --git a/src/tbf.cpp b/src/tbf.cpp index 29aed154..42d522bd 100644 --- a/src/tbf.cpp +++ b/src/tbf.cpp @@ -430,8 +430,8 @@ void gprs_rlcmac_tbf::stop_timer() void gprs_rlcmac_tbf::poll_timeout() { - LOGP(DRLCMAC, LOGL_NOTICE, "%s poll timeout\n", - tbf_name(this)); + LOGP(DRLCMAC, LOGL_NOTICE, "%s poll timeout for FN=%d (curr FN %d)\n", + tbf_name(this), poll_fn, bts->current_frame_number()); poll_state = GPRS_RLCMAC_POLL_NONE; @@ -864,6 +864,9 @@ struct msgb *gprs_rlcmac_tbf::create_dl_ass(uint32_t fn) poll_state = GPRS_RLCMAC_POLL_SCHED; poll_fn = (fn + 13) % 2715648; dl_ass_state = GPRS_RLCMAC_DL_ASS_WAIT_ACK; + LOGP(DRLCMACDL, LOGL_INFO, + "%s Scheduled DL Assignment polling on FN=%d\n", + name(), poll_fn); } else { dl_ass_state = GPRS_RLCMAC_DL_ASS_NONE; new_dl_tbf->set_state(GPRS_RLCMAC_FLOW); @@ -930,6 +933,9 @@ struct msgb *gprs_rlcmac_tbf::create_ul_ass(uint32_t fn) poll_state = GPRS_RLCMAC_POLL_SCHED; poll_fn = (fn + 13) % 2715648; ul_ass_state = GPRS_RLCMAC_UL_ASS_WAIT_ACK; + LOGP(DRLCMACDL, LOGL_INFO, + "%s Scheduled UL Assignment polling on FN=%d\n", + name(), poll_fn); return msg; } diff --git a/src/tbf_dl.cpp b/src/tbf_dl.cpp index 39a1f334..b57e10e0 100644 --- a/src/tbf_dl.cpp +++ b/src/tbf_dl.cpp @@ -686,6 +686,10 @@ struct msgb *gprs_rlcmac_dl_tbf::create_dl_acked_block( rh->s_p = 1; /* Polling */ m_last_dl_poll_fn = poll_fn; + + LOGP(DRLCMACDL, LOGL_INFO, + "%s Scheduled Ack/Nack polling on FN=%d, TS=%d\n", + name(), poll_fn, ts); } } diff --git a/tests/tbf/TbfTest.err b/tests/tbf/TbfTest.err index 55e46d0a..e49dd439 100644 --- a/tests/tbf/TbfTest.err +++ b/tests/tbf/TbfTest.err @@ -61,6 +61,7 @@ TBF(TFI=0 TLLI=0xffeeddcc DIR=DL STATE=FLOW) append TBF(TFI=0 TLLI=0xffeeddcc DIR=DL STATE=FLOW) start Packet Downlink Assignment (PACCH) +++++++++++++++++++++++++ TX : Packet Downlink Assignment +++++++++++++++++++++++++ ------------------------- TX : Packet Downlink Assignment ------------------------- +TBF(TFI=0 TLLI=0xffeeddcc DIR=DL STATE=FLOW) Scheduled DL Assignment polling on FN=13 Scheduling control message at RTS for TBF(TFI=0 TLLI=0xffeeddcc DIR=DL STATE=FLOW) (TRX=0, TS=4) Sending data request: trx=0 ts=4 sapi=5 arfcn=0 fn=0 block=0 data=4f 08 20 00 44 02 00 02 08 04 00 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b Scheduling data message at RTS for DL TFI=0 (TRX=0, TS=4) prio=3 @@ -138,6 +139,7 @@ TBF(TFI=0 TLLI=0xffeeddcc DIR=DL STATE=FLOW) append TBF(TFI=0 TLLI=0xffeeddcc DIR=DL STATE=FLOW) start Packet Downlink Assignment (PACCH) +++++++++++++++++++++++++ TX : Packet Downlink Assignment +++++++++++++++++++++++++ ------------------------- TX : Packet Downlink Assignment ------------------------- +TBF(TFI=0 TLLI=0xffeeddcc DIR=DL STATE=FLOW) Scheduled DL Assignment polling on FN=13 Scheduling control message at RTS for TBF(TFI=0 TLLI=0xffeeddcc DIR=DL STATE=FLOW) (TRX=0, TS=4) Sending data request: trx=0 ts=4 sapi=5 arfcn=0 fn=0 block=0 data=4f 08 20 00 44 02 00 02 08 04 00 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b Scheduling data message at RTS for DL TFI=0 (TRX=0, TS=4) prio=3 @@ -215,6 +217,7 @@ TBF(TFI=0 TLLI=0xffeeddcc DIR=DL STATE=FLOW) append TBF(TFI=0 TLLI=0xffeeddcc DIR=DL STATE=FLOW) start Packet Downlink Assignment (PACCH) +++++++++++++++++++++++++ TX : Packet Downlink Assignment +++++++++++++++++++++++++ ------------------------- TX : Packet Downlink Assignment ------------------------- +TBF(TFI=0 TLLI=0xffeeddcc DIR=DL STATE=FLOW) Scheduled DL Assignment polling on FN=13 Scheduling control message at RTS for TBF(TFI=0 TLLI=0xffeeddcc DIR=DL STATE=FLOW) (TRX=0, TS=4) Sending data request: trx=0 ts=4 sapi=5 arfcn=0 fn=0 block=0 data=4f 08 20 00 44 02 00 02 08 04 00 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b Scheduling data message at RTS for DL TFI=0 (TRX=0, TS=4) prio=3 @@ -1468,6 +1471,7 @@ Change control TS to 7 until assinment is complete. TBF(TFI=0 TLLI=0xf1223344 DIR=UL STATE=ASSIGN)s start Packet Uplink Assignment (PACCH) +++++++++++++++++++++++++ TX : Packet Uplink Assignment +++++++++++++++++++++++++ ------------------------- TX : Packet Uplink Assignment ------------------------- +TBF(TFI=0 TLLI=0xf1223344 DIR=UL STATE=ASSIGN) Scheduled UL Assignment polling on FN=2654283 Scheduling control message at RTS for TBF(TFI=0 TLLI=0xf1223344 DIR=UL STATE=ASSIGN) (TRX=0, TS=7) Sending data request: trx=0 ts=7 sapi=5 arfcn=0 fn=2654270 block=8 data=4f 28 5e 24 46 68 8f 1d 00 00 88 00 08 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b +++++++++++++++++++++++++ RX : Uplink Control Block +++++++++++++++++++++++++ @@ -1544,6 +1548,7 @@ Change control TS to 7 until assinment is complete. TBF(TFI=0 TLLI=0xf1223344 DIR=UL STATE=ASSIGN)s start Packet Uplink Assignment (PACCH) +++++++++++++++++++++++++ TX : Packet Uplink Assignment +++++++++++++++++++++++++ ------------------------- TX : Packet Uplink Assignment ------------------------- +TBF(TFI=0 TLLI=0xf1223344 DIR=UL STATE=ASSIGN) Scheduled UL Assignment polling on FN=2654283 Scheduling control message at RTS for TBF(TFI=0 TLLI=0xf1223344 DIR=UL STATE=ASSIGN) (TRX=0, TS=7) Sending data request: trx=0 ts=7 sapi=5 arfcn=0 fn=2654270 block=8 data=4f 28 5e 24 46 68 8f 1d 00 00 88 00 08 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b +++++++++++++++++++++++++ RX : Uplink Control Block +++++++++++++++++++++++++ @@ -1588,6 +1593,7 @@ Received RTS for PDCH: TRX=0 TS=7 FN=2654275 block_nr=9 scheduling USF=0 for req TBF(TFI=0 TLLI=0xf1223344 DIR=DL STATE=ASSIGN) start Packet Downlink Assignment (PACCH) +++++++++++++++++++++++++ TX : Packet Downlink Assignment +++++++++++++++++++++++++ ------------------------- TX : Packet Downlink Assignment ------------------------- +TBF(TFI=0 TLLI=0xf1223344 DIR=UL STATE=FLOW) Scheduled DL Assignment polling on FN=2654288 Scheduling control message at RTS for TBF(TFI=0 TLLI=0xf1223344 DIR=UL STATE=FLOW) (TRX=0, TS=7) Sending data request: trx=0 ts=7 sapi=5 arfcn=0 fn=2654275 block=9 data=48 08 00 00 0c 72 00 02 08 00 80 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b +++++++++++++++++++++++++ RX : Uplink Control Block +++++++++++++++++++++++++ @@ -1616,6 +1622,7 @@ data block: 07 01 00 29 52 41 55 5f 41 43 43 45 50 54 2b 2b 2b 2b 2b 2b 2b 2b 2b - Scheduling Ack/Nack polling, because is was requested explicitly (e.g. first final block sent). Polling sheduled in this TS 7 TBF(TFI=0 TLLI=0xf1223344 DIR=DL STATE=FINISHED) starting timer 3191. +TBF(TFI=0 TLLI=0xf1223344 DIR=DL STATE=FINISHED) Scheduled Ack/Nack polling on FN=2654292, TS=7 Sending data request: trx=0 ts=7 sapi=5 arfcn=0 fn=2654279 block=10 data=08 01 00 29 52 41 55 5f 41 43 43 45 50 54 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 00 Received RTS for PDCH: TRX=0 TS=7 FN=2654283 block_nr=11 scheduling USF=0 for required uplink resource of UL TFI=0 Scheduling data message at RTS for DL TFI=0 (TRX=0, TS=7) prio=1 @@ -1659,6 +1666,7 @@ Received RTS for PDCH: TRX=0 TS=7 FN=2654335 block_nr=11 scheduling USF=0 for re TBF(TFI=1 TLLI=0xf5667788 DIR=UL STATE=ASSIGN)s start Packet Uplink Assignment (PACCH) +++++++++++++++++++++++++ TX : Packet Uplink Assignment +++++++++++++++++++++++++ ------------------------- TX : Packet Uplink Assignment ------------------------- +TBF(TFI=1 TLLI=0xf5667788 DIR=UL STATE=ASSIGN) Scheduled UL Assignment polling on FN=2654348 Scheduling control message at RTS for TBF(TFI=1 TLLI=0xf5667788 DIR=UL STATE=ASSIGN) (TRX=0, TS=7) Sending data request: trx=0 ts=7 sapi=5 arfcn=0 fn=2654335 block=11 data=48 28 5e ac ce f1 0f 1d 00 00 88 40 09 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b +++++++++++++++++++++++++ RX : Uplink Control Block +++++++++++++++++++++++++ @@ -1721,6 +1729,7 @@ Change control TS to 7 until assinment is complete. TBF(TFI=0 TLLI=0xf1223344 DIR=UL STATE=ASSIGN)s start Packet Uplink Assignment (PACCH) +++++++++++++++++++++++++ TX : Packet Uplink Assignment +++++++++++++++++++++++++ ------------------------- TX : Packet Uplink Assignment ------------------------- +TBF(TFI=0 TLLI=0xf1223344 DIR=UL STATE=ASSIGN) Scheduled UL Assignment polling on FN=2654283 Scheduling control message at RTS for TBF(TFI=0 TLLI=0xf1223344 DIR=UL STATE=ASSIGN) (TRX=0, TS=7) Sending data request: trx=0 ts=7 sapi=5 arfcn=0 fn=2654270 block=8 data=4f 28 5e 24 46 68 83 1d 00 00 88 00 08 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b +++++++++++++++++++++++++ RX : Uplink Control Block +++++++++++++++++++++++++ @@ -1802,6 +1811,7 @@ Change control TS to 7 until assinment is complete. TBF(TFI=0 TLLI=0xf1223344 DIR=UL STATE=ASSIGN)s start Packet Uplink Assignment (PACCH) +++++++++++++++++++++++++ TX : Packet Uplink Assignment +++++++++++++++++++++++++ ------------------------- TX : Packet Uplink Assignment ------------------------- +TBF(TFI=0 TLLI=0xf1223344 DIR=UL STATE=ASSIGN) Scheduled UL Assignment polling on FN=2654340 Scheduling control message at RTS for TBF(TFI=0 TLLI=0xf1223344 DIR=UL STATE=ASSIGN) (TRX=0, TS=7) Sending data request: trx=0 ts=7 sapi=5 arfcn=0 fn=2654327 block=9 data=4f 28 5e 24 46 68 83 1d 00 00 88 00 08 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b +++++++++++++++++++++++++ RX : Uplink Control Block +++++++++++++++++++++++++ @@ -1855,6 +1865,7 @@ Change control TS to 7 until assinment is complete. TBF(TFI=0 TLLI=0xf1223344 DIR=UL STATE=ASSIGN)s start Packet Uplink Assignment (PACCH) +++++++++++++++++++++++++ TX : Packet Uplink Assignment +++++++++++++++++++++++++ ------------------------- TX : Packet Uplink Assignment ------------------------- +TBF(TFI=0 TLLI=0xf1223344 DIR=UL STATE=ASSIGN) Scheduled UL Assignment polling on FN=2654283 Scheduling control message at RTS for TBF(TFI=0 TLLI=0xf1223344 DIR=UL STATE=ASSIGN) (TRX=0, TS=7) Sending data request: trx=0 ts=7 sapi=5 arfcn=0 fn=2654270 block=8 data=4f 28 5e 24 46 68 83 1d 00 00 88 00 08 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b +++++++++++++++++++++++++ RX : Uplink Control Block +++++++++++++++++++++++++ @@ -1991,6 +2002,7 @@ Change control TS to 7 until assinment is complete. TBF(TFI=0 TLLI=0xf1223344 DIR=UL STATE=ASSIGN)s start Packet Uplink Assignment (PACCH) +++++++++++++++++++++++++ TX : Packet Uplink Assignment +++++++++++++++++++++++++ ------------------------- TX : Packet Uplink Assignment ------------------------- +TBF(TFI=0 TLLI=0xf1223344 DIR=UL STATE=ASSIGN) Scheduled UL Assignment polling on FN=2654283 Scheduling control message at RTS for TBF(TFI=0 TLLI=0xf1223344 DIR=UL STATE=ASSIGN) (TRX=0, TS=7) Sending data request: trx=0 ts=7 sapi=5 arfcn=0 fn=2654270 block=8 data=4f 28 5e 24 46 68 83 1d 00 00 88 00 08 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b +++++++++++++++++++++++++ RX : Uplink Control Block +++++++++++++++++++++++++ @@ -2074,6 +2086,7 @@ Received RTS for PDCH: TRX=0 TS=7 FN=2654275 block_nr=9 scheduling USF=0 for req TBF(TFI=0 TLLI=0xf1223344 DIR=DL STATE=ASSIGN) start Packet Downlink Assignment (PACCH) +++++++++++++++++++++++++ TX : Packet Downlink Assignment +++++++++++++++++++++++++ ------------------------- TX : Packet Downlink Assignment ------------------------- +TBF(TFI=0 TLLI=0xf1223344 DIR=UL STATE=FLOW) Scheduled DL Assignment polling on FN=2654288 Scheduling control message at RTS for TBF(TFI=0 TLLI=0xf1223344 DIR=UL STATE=FLOW) (TRX=0, TS=7) Sending data request: trx=0 ts=7 sapi=5 arfcn=0 fn=2654275 block=9 data=48 08 00 00 0c 72 00 02 08 00 80 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b +++++++++++++++++++++++++ RX : Uplink Control Block +++++++++++++++++++++++++ @@ -2468,6 +2481,7 @@ Complete DL frame for TBF(TFI=0 TLLI=0xf1223344 DIR=DL STATE=FLOW)len=13 data block: 07 00 28 16 35 45 54 20 32 38 4c 4c 43 20 50 41 43 4b 45 54 20 32 39 - Scheduling Ack/Nack polling, because 20 blocks sent. Polling sheduled in this TS 7 +TBF(TFI=0 TLLI=0xf1223344 DIR=DL STATE=FLOW) Scheduled Ack/Nack polling on FN=2654379, TS=7 Sending data request: trx=0 ts=7 sapi=5 arfcn=0 fn=2654366 block=6 data=08 00 28 16 35 45 54 20 32 38 4c 4c 43 20 50 41 43 4b 45 54 20 32 39 Received RTS on disabled PDCH: TRX=0 TS=0 Received RTS on disabled PDCH: TRX=0 TS=1 @@ -2639,6 +2653,7 @@ Received RTS for PDCH: TRX=0 TS=7 FN=2654400 block_nr=2 scheduling USF=0 for req TBF(TFI=1 TLLI=0xf1223344 DIR=DL STATE=ASSIGN) start Packet Downlink Assignment (PACCH) +++++++++++++++++++++++++ TX : Packet Downlink Assignment +++++++++++++++++++++++++ ------------------------- TX : Packet Downlink Assignment ------------------------- +TBF(TFI=0 TLLI=0xf1223344 DIR=DL STATE=WAIT RELEASE) Scheduled DL Assignment polling on FN=2654413 Scheduling control message at RTS for TBF(TFI=0 TLLI=0xf1223344 DIR=DL STATE=WAIT RELEASE) (TRX=0, TS=7) Sending data request: trx=0 ts=7 sapi=5 arfcn=0 fn=2654400 block=2 data=48 08 20 08 0c 72 00 02 18 00 80 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b +++++++++++++++++++++++++ RX : Uplink Control Block +++++++++++++++++++++++++ @@ -2840,4 +2855,5 @@ data block: 07 03 14 4d 43 20 50 41 43 4b 45 54 20 30 39 20 28 54 42 46 20 32 29 - Scheduling Ack/Nack polling, because is was requested explicitly (e.g. first final block sent). Polling sheduled in this TS 7 TBF(TFI=1 TLLI=0xf1223344 DIR=DL STATE=FINISHED) starting timer 3191. +TBF(TFI=1 TLLI=0xf1223344 DIR=DL STATE=FINISHED) Scheduled Ack/Nack polling on FN=2654461, TS=7 Sending data request: trx=0 ts=7 sapi=5 arfcn=0 fn=2654448 block=1 data=08 03 14 4d 43 20 50 41 43 4b 45 54 20 30 39 20 28 54 42 46 20 32 29 |