rlcmac: defer going to pkt_idle_timer after freeing TBF

Give some time to pending tx blocks to be transmitted before jumping
back to CCCH.

Change-Id: I563ad2ee6aacd65314e998626dc27adc29221a7d

5 files changed, 54 insertions, 10 deletions

diff --git a/include/osmocom/gprs/rlcmac/gre.h b/include/osmocom/gprs/rlcmac/gre.h
index 0e17836..befcf05 100644
--- a/include/osmocom/gprs/rlcmac/gre.h
+++ b/include/osmocom/gprs/rlcmac/gre.h
@@ -1,6 +1,8 @@
 /* GPRS RLC/MAC Entity (one per MS) */
 #pragma once
 
+#include <osmocom/gsm/gsm0502.h>
+
 #include <osmocom/gprs/rlcmac/rlcmac.h>
 #include <osmocom/gprs/rlcmac/llc_queue.h>
 #include <osmocom/gprs/rlcmac/tbf_dl_ass_fsm.h>
@@ -9,6 +11,13 @@ struct gprs_rlcmac_dl_tbf;
 struct gprs_rlcmac_ul_tbf;
 struct gprs_rlcmac_tbf;
 
+/* We have to defer going to CCCH a bit to leave space for last PKT CTRL ACK to be transmitted
+ * The Uplink TDMA clock is (1 FN + 3 TS = 8+3 = 11 TS) delayed with regards to the Downlink.
+ * Furthermore, the UL block is distributed over next 4 FNs (8*4= 32 TS).
+ * That makes a total of 43 TS: 43 / 8 = 5.375 FNs of time required.
+ */
+#define DEFER_SCHED_PDCH_REL_REQ_uS (GSM_TDMA_FN_DURATION_uS*6) /* > GSM_TDMA_FN_DURATION_uS * 5.375 */
+
 struct gprs_rlcmac_entity {
 	struct llist_head entry; /* item in (struct gprs_rlcmac_ctx)->gre_list */
 	uint32_t tlli;
@@ -26,6 +35,7 @@ struct gprs_rlcmac_entity {
 	struct gprs_rlcmac_ul_tbf *ul_tbf;
 
 	bool freeing; /* Set to true during destructor */
+	struct osmo_timer_list defer_pkt_idle_timer;
 };
 
 struct gprs_rlcmac_entity *gprs_rlcmac_entity_alloc(uint32_t tlli);
diff --git a/src/rlcmac/gre.c b/src/rlcmac/gre.c
index 9021faa..3d2297f 100644
--- a/src/rlcmac/gre.c
+++ b/src/rlcmac/gre.c
@@ -35,6 +35,15 @@
 #include <osmocom/gprs/rlcmac/gre.h>
 #include <osmocom/gprs/rlcmac/rlcmac_enc.h>
 
+
+/* We have to defer going to CCCH a bit to leave space for last PKT CTRL ACK to be transmitted */
+static void _defer_pkt_idle_timer_cb(void *data)
+{
+	struct gprs_rlcmac_entity *gre = data;
+	gprs_rlcmac_submit_l1ctl_pdch_rel_req();
+	gprs_rlcmac_entity_start_ul_tbf_pkt_acc_proc_if_needed(gre);
+}
+
 struct gprs_rlcmac_entity *gprs_rlcmac_entity_alloc(uint32_t tlli)
 {
 	struct gprs_rlcmac_entity *gre;
@@ -44,6 +53,8 @@ struct gprs_rlcmac_entity *gprs_rlcmac_entity_alloc(uint32_t tlli)
 	if (!gre)
 		return NULL;
 
+	osmo_timer_setup(&gre->defer_pkt_idle_timer, _defer_pkt_idle_timer_cb, gre);
+
 	gre->llc_queue = gprs_rlcmac_llc_queue_alloc(gre);
 	if (!gre->llc_queue)
 		goto err_free_gre;
@@ -73,6 +84,8 @@ void gprs_rlcmac_entity_free(struct gprs_rlcmac_entity *gre)
 
 	gre->freeing = true;
 
+	osmo_timer_del(&gre->defer_pkt_idle_timer);
+
 	gprs_rlcmac_tbf_dl_ass_fsm_destructor(&gre->dl_tbf_dl_ass_fsm);
 	gprs_rlcmac_dl_tbf_free(gre->dl_tbf);
 	gprs_rlcmac_ul_tbf_free(gre->ul_tbf);
@@ -111,8 +124,8 @@ void gprs_rlcmac_entity_dl_tbf_freed(struct gprs_rlcmac_entity *gre, const struc
 	/* we have no DL nor UL TBFs. Go back to PACKET-IDLE state, and start
 	 * packet-access-procedure if we still have data to be transmitted.
 	 */
-	gprs_rlcmac_submit_l1ctl_pdch_rel_req();
-	gprs_rlcmac_entity_start_ul_tbf_pkt_acc_proc_if_needed(gre);
+	/* We have to defer going to CCCH a bit to leave space for last PKT CTRL ACK to be transmitted */
+	osmo_timer_schedule(&gre->defer_pkt_idle_timer, 0, DEFER_SCHED_PDCH_REL_REQ_uS);
 }
 
 /* Called by ul_tbf destructor to inform the UL TBF pointer has been freed.
@@ -145,8 +158,8 @@ void gprs_rlcmac_entity_ul_tbf_freed(struct gprs_rlcmac_entity *gre, const struc
 	/* we have no DL nor UL TBFs. Go back to PACKET-IDLE state, and start
 	 * packet-access-procedure if we still have data to be transmitted.
 	 */
-	gprs_rlcmac_submit_l1ctl_pdch_rel_req();
-	gprs_rlcmac_entity_start_ul_tbf_pkt_acc_proc_if_needed(gre);
+	/* We have to defer going to CCCH a bit to leave space for last PKT CTRL ACK to be transmitted */
+	osmo_timer_schedule(&gre->defer_pkt_idle_timer, 0, DEFER_SCHED_PDCH_REL_REQ_uS);
 }
 
 /* TS 44.060 5.3 In packet idle mode:
diff --git a/tests/rlcmac/rlcmac_prim_test.c b/tests/rlcmac/rlcmac_prim_test.c
index 5ac2c32..0c40737 100644
--- a/tests/rlcmac/rlcmac_prim_test.c
+++ b/tests/rlcmac/rlcmac_prim_test.c
@@ -566,6 +566,17 @@ void prepare_test(void)
 
 void cleanup_test(void)
 {
+	struct gprs_rlcmac_entity *gre;
+	llist_for_each_entry(gre, &g_rlcmac_ctx->gre_list, entry) {
+		if (osmo_timer_pending(&gre->defer_pkt_idle_timer)) {
+			/* increase time DEFER_SCHED_PDCH_REL_REQ_uS, defer_pkt_idle_timer should trigger */
+			clock_override_add(0, DEFER_SCHED_PDCH_REL_REQ_uS);
+			clock_debug("Expect defer_pkt_idle_timer timeout");
+			osmo_select_main(0);
+			break;
+		}
+	}
+
 	/* Reinit the RLCMAC layer so that data generated during the test is freed within the test context: */
 	osmo_gprs_rlcmac_init(OSMO_GPRS_RLCMAC_LOCATION_MS);
 }
diff --git a/tests/rlcmac/rlcmac_prim_test.err b/tests/rlcmac/rlcmac_prim_test.err
index 5f8cbbb..087e371 100644
--- a/tests/rlcmac/rlcmac_prim_test.err
+++ b/tests/rlcmac/rlcmac_prim_test.err
@@ -689,9 +689,9 @@ DLGLOBAL INFO UL_TBF_ASS{IDLE}: Deallocated
 DLGLOBAL INFO UL_TBF{FINISHED}: Send L1CTL-CFG_UL_TBF.req ul_tbf_nr=0 (release)
 DLGLOBAL DEBUG Tx to lower layers: L1CTL-CFG_UL_TBF.request
 DLGLOBAL INFO UL_TBF{FINISHED}: Deallocated
+DLGLOBAL DEBUG Tx to lower layers: L1CTL-PDCH_DATA.request
 DLGLOBAL INFO Tx L1CTL-PDCH_REL.req
 DLGLOBAL DEBUG Tx to lower layers: L1CTL-PDCH_RELEASE.request
-DLGLOBAL DEBUG Tx to lower layers: L1CTL-PDCH_DATA.request
 DLGLOBAL INFO DL_TBF_ASS{IDLE}: Deallocated
 DLGLOBAL DEBUG Rx from lower layers: L1CTL-CCCH_DATA.indication
 DLGLOBAL DEBUG Rx SI13 from lower layers
diff --git a/tests/rlcmac/rlcmac_prim_test.ok b/tests/rlcmac/rlcmac_prim_test.ok
index a3e82c3..731bd20 100644
--- a/tests/rlcmac/rlcmac_prim_test.ok
+++ b/tests/rlcmac/rlcmac_prim_test.ok
@@ -8,8 +8,10 @@ test_rlcmac_prim_down_cb(): Rx L1CTL-PDCH_DATA.request fn=4 ts=7 data_len=34 dat
 test_rlcmac_prim_down_cb(): Rx L1CTL-PDCH_DATA.request fn=8 ts=7 data_len=34 data=[00 01 02 1d 00 00 23 42 11 e5 10 00 e2 18 f2 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 00 ]
 test_rlcmac_prim_down_cb(): Rx L1CTL-PDCH_DATA.request fn=21 ts=7 data_len=23 data=[40 04 00 00 8d 08 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b ]
 test_rlcmac_prim_down_cb(): Rx L1CTL-CFG_UL_TBF.request ul_tbf_nr=0 ul_slotmask=0x00
-test_rlcmac_prim_down_cb(): Rx L1CTL-PDCH_RELEASE.request
 === test_ul_tbf_attach end ===
+sys={0.027690}, mono={0.027690}: clock_override_add
+sys={0.027690}, mono={0.027690}: Expect defer_pkt_idle_timer timeout
+test_rlcmac_prim_down_cb(): Rx L1CTL-PDCH_RELEASE.request
 === test_ul_tbf_t3164_timeout start ===
 sys={0.000000}, mono={0.000000}: clock_override_set
 test_rlcmac_prim_down_cb(): Rx L1CTL-RACH.request ra=0x79
@@ -39,9 +41,11 @@ test_rlcmac_prim_down_cb(): Rx L1CTL-CFG_UL_TBF.request ul_tbf_nr=0 ul_slotmask=
 sys={20.000000}, mono={20.000000}: clock_override_add
 sys={20.000000}, mono={20.000000}: Expect T3164 timeout
 test_rlcmac_prim_down_cb(): Rx L1CTL-CFG_UL_TBF.request ul_tbf_nr=0 ul_slotmask=0x00
+=== test_ul_tbf_t3164_timeout end ===
+sys={20.027690}, mono={20.027690}: clock_override_add
+sys={20.027690}, mono={20.027690}: Expect defer_pkt_idle_timer timeout
 test_rlcmac_prim_down_cb(): Rx L1CTL-PDCH_RELEASE.request
 test_rlcmac_prim_down_cb(): Rx L1CTL-RACH.request ra=0x7a
-=== test_ul_tbf_t3164_timeout end ===
 test_rlcmac_prim_down_cb(): Rx L1CTL-CFG_UL_TBF.request ul_tbf_nr=1 ul_slotmask=0x00
 === test_ul_tbf_t3166_timeout start ===
 sys={0.000000}, mono={0.000000}: clock_override_set
@@ -77,8 +81,10 @@ test_rlcmac_prim_down_cb(): Rx L1CTL-PDCH_DATA.request fn=4 ts=7 data_len=34 dat
 sys={20.000000}, mono={20.000000}: clock_override_add
 sys={20.000000}, mono={20.000000}: Expect T3166 timeout
 test_rlcmac_prim_down_cb(): Rx L1CTL-CFG_UL_TBF.request ul_tbf_nr=0 ul_slotmask=0x00
-test_rlcmac_prim_down_cb(): Rx L1CTL-PDCH_RELEASE.request
 === test_ul_tbf_t3166_timeout end ===
+sys={20.027690}, mono={20.027690}: clock_override_add
+sys={20.027690}, mono={20.027690}: Expect defer_pkt_idle_timer timeout
+test_rlcmac_prim_down_cb(): Rx L1CTL-PDCH_RELEASE.request
 === test_ul_tbf_n3104_timeout start ===
 sys={0.000000}, mono={0.000000}: clock_override_set
 test_rlcmac_prim_down_cb(): Rx L1CTL-RACH.request ra=0x7b
@@ -128,8 +134,10 @@ test_rlcmac_prim_down_cb(): Rx L1CTL-PDCH_DATA.request fn=8 ts=7 data_len=34 dat
 sys={5.000000}, mono={5.000000}: clock_override_add
 sys={5.000000}, mono={5.000000}: Expect T3182 timeout
 test_rlcmac_prim_down_cb(): Rx L1CTL-CFG_UL_TBF.request ul_tbf_nr=0 ul_slotmask=0x00
-test_rlcmac_prim_down_cb(): Rx L1CTL-PDCH_RELEASE.request
 === test_ul_tbf_t3182_timeout end ===
+sys={5.027690}, mono={5.027690}: clock_override_add
+sys={5.027690}, mono={5.027690}: Expect defer_pkt_idle_timer timeout
+test_rlcmac_prim_down_cb(): Rx L1CTL-PDCH_RELEASE.request
 === test_ul_tbf_last_data_cv0_retrans_max start ===
 sys={0.000000}, mono={0.000000}: clock_override_set
 test_rlcmac_prim_down_cb(): Rx L1CTL-RACH.request ra=0x7b
@@ -146,9 +154,11 @@ RTS 2: FN=21
 test_rlcmac_prim_down_cb(): Rx L1CTL-PDCH_DATA.request fn=21 ts=7 data_len=34 data=[00 00 02 1d 11 e5 10 00 e2 18 f2 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 00 ]
 RTS 3: FN=26
 test_rlcmac_prim_down_cb(): Rx L1CTL-CFG_UL_TBF.request ul_tbf_nr=0 ul_slotmask=0x00
-test_rlcmac_prim_down_cb(): Rx L1CTL-PDCH_RELEASE.request
 test_rlcmac_prim_down_cb(): Rx L1CTL-PDCH_DATA.request fn=26 ts=7 data_len=34 data=[00 00 02 1d 11 e5 10 00 e2 18 f2 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 2b 00 ]
 === test_ul_tbf_last_data_cv0_retrans_max end ===
+sys={0.027690}, mono={0.027690}: clock_override_add
+sys={0.027690}, mono={0.027690}: Expect defer_pkt_idle_timer timeout
+test_rlcmac_prim_down_cb(): Rx L1CTL-PDCH_RELEASE.request
 === test_ul_tbf_countdown_procedure start ===
 sys={0.000000}, mono={0.000000}: clock_override_set
 test_rlcmac_prim_down_cb(): Rx L1CTL-RACH.request ra=0x7e