Adding flow chart diagram of ongoing TBFs and their events

It is quite essential. It shows how TBFs are related and helps to estimate
states and timers (timeouts) of the MS.

In order to use it, it must be defined by a switch at gprs_rlcmac.h.

4 files changed, 180 insertions, 4 deletions

diff --git a/src/gprs_rlcmac.cpp b/src/gprs_rlcmac.cpp
index fcd92c64..b5e0f352 100644
--- a/src/gprs_rlcmac.cpp
+++ b/src/gprs_rlcmac.cpp
@@ -89,6 +89,90 @@ llist_head *gprs_rlcmac_tbfs_lists[] = {
 };
 extern void *tall_pcu_ctx;
 
+#ifdef DEBUG_DIAGRAM
+struct timeval diagram_time = {0,0};
+struct timeval diagram_last_tv = {0,0};
+
+void debug_diagram(int diag, const char *format, ...)
+{
+	va_list ap;
+	char debug[128];
+	char line[1024];
+	struct gprs_rlcmac_tbf *tbf, *tbf_a[16];
+	int max_diag = -1, i;
+	uint64_t diff = 0;
+
+	va_start(ap, format);
+	vsnprintf(debug, sizeof(debug) - 1, format, ap);
+	debug[19] = ' ';
+	debug[20] = '\0';
+	va_end(ap);
+
+	memset(tbf_a, 0, sizeof(tbf_a));
+	llist_for_each_entry(tbf, &gprs_rlcmac_ul_tbfs, list) {
+		if (tbf->diag < 16) {
+			if (tbf->diag > max_diag)
+				max_diag = tbf->diag;
+			tbf_a[tbf->diag] = tbf;
+		}
+	}
+	llist_for_each_entry(tbf, &gprs_rlcmac_dl_tbfs, list) {
+		if (tbf->diag < 16) {
+			if (tbf->diag > max_diag)
+				max_diag = tbf->diag;
+			tbf_a[tbf->diag] = tbf;
+		}
+	}
+
+	if (diagram_last_tv.tv_sec) {
+		diff = (uint64_t)(diagram_time.tv_sec -
+					diagram_last_tv.tv_sec) * 1000;
+		diff += diagram_time.tv_usec / 1000;
+		diff -= diagram_last_tv.tv_usec / 1000;
+	}
+	memcpy(&diagram_last_tv, &diagram_time, sizeof(struct timeval));
+
+	if (diff > 0) {
+		if (diff > 99999)
+			strcpy(line, "  ...  : ");
+		else
+			sprintf(line, "%3d.%03d: ", (int)(diff / 1000),
+				(int)(diff % 1000));
+		for (i = 0; i <= max_diag; i++) {
+			if (tbf_a[i] == NULL) {
+				strcat(line, "                    ");
+				continue;
+			}
+			if (tbf_a[i]->diag_new) {
+				strcat(line, "         |          ");
+				continue;
+			}
+			strcat(line, "                    ");
+		}
+		puts(line);
+	}
+	strcpy(line, "       : ");
+	for (i = 0; i <= max_diag; i++) {
+		if (tbf_a[i] == NULL) {
+			strcat(line, "                    ");
+			continue;
+		}
+		if (tbf_a[i]->diag != diag) {
+			strcat(line, "         |          ");
+			continue;
+		}
+		if (strlen(debug) < 19) {
+			strcat(line, "                    ");
+			memcpy(line + strlen(line) - 11 - strlen(debug) / 2,
+				debug, strlen(debug));
+		} else
+			strcat(line, debug);
+		tbf_a[i]->diag_new = 1;
+	}
+	puts(line);
+}
+#endif
+
 /* FIXME: spread ressources over multiple TRX. Also add option to use same
  * TRX in case of existing TBF for TLLI in the other direction. */
 /* search for free TFI and return TFI, TRX and first TS */
@@ -246,6 +330,24 @@ struct gprs_rlcmac_tbf *tbf_alloc(struct gprs_rlcmac_tbf *old_tbf,
 	struct gprs_rlcmac_tbf *tbf;
 	int rc;
 
+#ifdef DEBUG_DIAGRAM
+	/* hunt for first free number in diagram */
+	int diagram_num;
+	for (diagram_num = 0; ; diagram_num++) {
+		llist_for_each_entry(tbf, &gprs_rlcmac_ul_tbfs, list) {
+			if (tbf->diag == diagram_num)
+				goto next_diagram;
+		}
+		llist_for_each_entry(tbf, &gprs_rlcmac_dl_tbfs, list) {
+			if (tbf->diag == diagram_num)
+				goto next_diagram;
+		}
+		break;
+next_diagram:
+		continue;
+	}
+#endif
+
 	LOGP(DRLCMAC, LOGL_DEBUG, "********** TBF starts here **********\n");
 	LOGP(DRLCMAC, LOGL_INFO, "Allocating %s TBF: TFI=%d TRX=%d "
 		"MS_CLASS=%d\n", (dir == GPRS_RLCMAC_UL_TBF) ? "UL" : "DL",
@@ -258,6 +360,9 @@ struct gprs_rlcmac_tbf *tbf_alloc(struct gprs_rlcmac_tbf *old_tbf,
 	if (!tbf)
 		return NULL;
 
+#ifdef DEBUG_DIAGRAM
+	tbf->diag = diagram_num;
+#endif
 	tbf->direction = dir;
 	tbf->tfi = tfi;
 	tbf->trx = trx;
@@ -296,6 +401,11 @@ struct gprs_rlcmac_tbf *tbf_alloc(struct gprs_rlcmac_tbf *old_tbf,
 	else
 		llist_add(&tbf->list, &gprs_rlcmac_dl_tbfs);
 
+	debug_diagram(tbf->diag, "+-----------------+");
+	debug_diagram(tbf->diag, "|NEW %s TBF TFI=%2d|",
+		(dir == GPRS_RLCMAC_UL_TBF) ? "UL" : "DL", tfi);
+	debug_diagram(tbf->diag, "+-----------------+");
+
 	return tbf;
 }
 
@@ -741,6 +851,9 @@ void tbf_free(struct gprs_rlcmac_tbf *tbf)
 {
 	struct msgb *msg;
 
+	debug_diagram(tbf->diag, "+---------------+");
+	debug_diagram(tbf->diag, "|    THE END    |");
+	debug_diagram(tbf->diag, "+---------------+");
 	LOGP(DRLCMAC, LOGL_INFO, "Free %s TBF=%d with TLLI=0x%08x.\n",
 		(tbf->direction == GPRS_RLCMAC_UL_TBF) ? "UL" : "DL", tbf->tfi,
 		tbf->tlli);
@@ -818,6 +931,7 @@ const char *tbf_state_name[] = {
 void tbf_new_state(struct gprs_rlcmac_tbf *tbf,
 	enum gprs_rlcmac_tbf_state state)
 {
+	debug_diagram(tbf->diag, "->%s", tbf_state_name[state]);
 	LOGP(DRLCMAC, LOGL_DEBUG, "%s TBF=%d changes state from %s to %s\n",
 		(tbf->direction == GPRS_RLCMAC_UL_TBF) ? "UL" : "DL", tbf->tfi,
 		tbf_state_name[tbf->state], tbf_state_name[state]);
diff --git a/src/gprs_rlcmac.h b/src/gprs_rlcmac.h
index 1900d89b..c67a68bd 100644
--- a/src/gprs_rlcmac.h
+++ b/src/gprs_rlcmac.h
@@ -31,6 +31,9 @@ extern "C" {
 }
 #endif
 
+/* generate a diagram for debugging timing issues */
+//#define DEBUG_DIAGRAM
+
 /* This special feature will delay assignment of downlink TBF by one second,
  * in case there is already a TBF.
  * This is usefull to debug downlink establishment during packet idle mode.
@@ -225,6 +228,11 @@ struct gprs_rlcmac_tbf {
 	uint32_t bw_octets; /* number of octets transmitted since bw_tv */
 
 	uint8_t cs; /* current coding scheme */
+
+#ifdef DEBUG_DIAGRAM
+	int diag; /* number where TBF is presented in diagram */
+	int diag_new; /* used to format output of new TBF */
+#endif
 };
 
 extern struct llist_head gprs_rlcmac_ul_tbfs; /* list of uplink TBFs */
@@ -262,6 +270,12 @@ struct gprs_rlcmac_cs {
 
 extern struct gprs_rlcmac_cs gprs_rlcmac_cs[];
 
+#ifdef DEBUG_DIAGRAM
+void debug_diagram(int diag, const char *format, ...);
+#else
+#define debug_diagram(a, b, args...) ;
+#endif
+
 int sba_alloc(uint8_t *_trx, uint8_t *_ts, uint32_t *_fn, uint8_t ta);
 
 struct gprs_rlcmac_sba *sba_find(uint8_t trx, uint8_t ts, uint32_t fn);
diff --git a/src/gprs_rlcmac_data.cpp b/src/gprs_rlcmac_data.cpp
index edc324b0..776c416f 100644
--- a/src/gprs_rlcmac_data.cpp
+++ b/src/gprs_rlcmac_data.cpp
@@ -109,6 +109,7 @@ int gprs_rlcmac_poll_timeout(struct gprs_rlcmac_tbf *tbf)
 			tbf->state_flags |= (1 << GPRS_RLCMAC_FLAG_TO_UL_ACK);
 		}
 		tbf->ul_ack_state = GPRS_RLCMAC_UL_ACK_NONE;
+		debug_diagram(tbf->diag, "timeout UL-ACK");
 		if (tbf->state == GPRS_RLCMAC_FINISHED) {
 			struct gprs_rlcmac_bts *bts = gprs_rlcmac_bts;
 
@@ -116,6 +117,7 @@ int gprs_rlcmac_poll_timeout(struct gprs_rlcmac_tbf *tbf)
 			if (tbf->dir.ul.n3103 == bts->n3103) {
 				LOGP(DRLCMAC, LOGL_NOTICE,
 					"- N3103 exceeded\n");
+				debug_diagram(tbf->diag, "N3103 exceeded");
 				tbf_new_state(tbf, GPRS_RLCMAC_RELEASING);
 				tbf_timer_start(tbf, 3169, bts->t3169, 0);
 				return 0;
@@ -135,9 +137,11 @@ int gprs_rlcmac_poll_timeout(struct gprs_rlcmac_tbf *tbf)
 			tbf->state_flags |= (1 << GPRS_RLCMAC_FLAG_TO_UL_ASS);
 		}
 		tbf->ul_ass_state = GPRS_RLCMAC_UL_ASS_NONE;
+		debug_diagram(tbf->diag, "timeout UL-ASS");
 		tbf->n3105++;
 		if (tbf->n3105 == bts->n3105) {
 			LOGP(DRLCMAC, LOGL_NOTICE, "- N3105 exceeded\n");
+			debug_diagram(tbf->diag, "N3105 exceeded");
 			tbf_new_state(tbf, GPRS_RLCMAC_RELEASING);
 			tbf_timer_start(tbf, 3195, bts->t3195, 0);
 			return 0;
@@ -156,9 +160,11 @@ int gprs_rlcmac_poll_timeout(struct gprs_rlcmac_tbf *tbf)
 			tbf->state_flags |= (1 << GPRS_RLCMAC_FLAG_TO_DL_ASS);
 		}
 		tbf->dl_ass_state = GPRS_RLCMAC_DL_ASS_NONE;
+		debug_diagram(tbf->diag, "timeout DL-ASS");
 		tbf->n3105++;
 		if (tbf->n3105 == bts->n3105) {
 			LOGP(DRLCMAC, LOGL_NOTICE, "- N3105 exceeded\n");
+			debug_diagram(tbf->diag, "N3105 exceeded");
 			tbf_new_state(tbf, GPRS_RLCMAC_RELEASING);
 			tbf_timer_start(tbf, 3195, bts->t3195, 0);
 			return 0;
@@ -175,9 +181,11 @@ int gprs_rlcmac_poll_timeout(struct gprs_rlcmac_tbf *tbf)
 			gprs_rlcmac_diag(tbf);
 			tbf->state_flags |= (1 << GPRS_RLCMAC_FLAG_TO_DL_ACK);
 		}
+		debug_diagram(tbf->diag, "timeout DL-ACK");
 		tbf->n3105++;
 		if (tbf->n3105 == bts->n3105) {
 			LOGP(DRLCMAC, LOGL_NOTICE, "- N3105 exceeded\n");
+			debug_diagram(tbf->diag, "N3105 exceeded");
 			tbf_new_state(tbf, GPRS_RLCMAC_RELEASING);
 			tbf_timer_start(tbf, 3195, bts->t3195, 0);
 			return 0;
@@ -286,12 +294,13 @@ int gprs_rlcmac_rcv_control_block(bitvec *rlc_block, uint8_t trx, uint8_t ts,
 		if (tbf->ul_ack_state == GPRS_RLCMAC_UL_ACK_WAIT_ACK) {
 			LOGP(DRLCMAC, LOGL_DEBUG, "TBF: [UPLINK] END TFI: %u TLLI: 0x%08x \n", tbf->tfi, tbf->tlli);
 			tbf->ul_ack_state = GPRS_RLCMAC_UL_ACK_NONE;
+			debug_diagram(tbf->diag, "got CTL-ACK (fin)");
 			if ((tbf->state_flags &
 				(1 << GPRS_RLCMAC_FLAG_TO_UL_ACK))) {
 				tbf->state_flags &=
 					~(1 << GPRS_RLCMAC_FLAG_TO_UL_ACK);
 				LOGP(DRLCMAC, LOGL_NOTICE, "Recovered uplink "
-					"ack\n");
+					"ack for UL TBF=%d\n", tbf->tfi);
 			}
 			tbf_free(tbf);
 			break;
@@ -301,6 +310,7 @@ int gprs_rlcmac_rcv_control_block(bitvec *rlc_block, uint8_t trx, uint8_t ts,
 			/* reset N3105 */
 			tbf->n3105 = 0;
 			tbf->dl_ass_state = GPRS_RLCMAC_DL_ASS_NONE;
+			debug_diagram(tbf->diag, "got CTL-ACK DL-ASS");
 			if (tbf->direction == GPRS_RLCMAC_UL_TBF)
 				tbf = tbf_by_tlli(tbf->tlli,
 							GPRS_RLCMAC_DL_TBF);
@@ -317,7 +327,7 @@ int gprs_rlcmac_rcv_control_block(bitvec *rlc_block, uint8_t trx, uint8_t ts,
 				tbf->state_flags &=
 					~(1 << GPRS_RLCMAC_FLAG_TO_DL_ASS);
 				LOGP(DRLCMAC, LOGL_NOTICE, "Recovered downlink "
-					"assignment\n");
+					"assignment for DL TBF=%d\n", tbf->tfi);
 			}
 			tbf_assign_control_ts(tbf);
 			break;
@@ -327,6 +337,7 @@ int gprs_rlcmac_rcv_control_block(bitvec *rlc_block, uint8_t trx, uint8_t ts,
 			/* reset N3105 */
 			tbf->n3105 = 0;
 			tbf->ul_ass_state = GPRS_RLCMAC_UL_ASS_NONE;
+			debug_diagram(tbf->diag, "got CTL-AC UL-ASS");
 			if (tbf->direction == GPRS_RLCMAC_DL_TBF)
 				tbf = tbf_by_tlli(tbf->tlli,
 							GPRS_RLCMAC_UL_TBF);
@@ -341,7 +352,7 @@ int gprs_rlcmac_rcv_control_block(bitvec *rlc_block, uint8_t trx, uint8_t ts,
 				tbf->state_flags &=
 					~(1 << GPRS_RLCMAC_FLAG_TO_UL_ASS);
 				LOGP(DRLCMAC, LOGL_NOTICE, "Recovered uplink "
-					"assignment\n");
+					"assignment for UL TBF=%d\n", tbf->tfi);
 			}
 			tbf_assign_control_ts(tbf);
 			break;
@@ -370,6 +381,7 @@ int gprs_rlcmac_rcv_control_block(bitvec *rlc_block, uint8_t trx, uint8_t ts,
 		tlli = tbf->tlli;
 		LOGP(DRLCMAC, LOGL_DEBUG, "RX: [PCU <- BTS] TFI: %u TLLI: 0x%08x Packet Downlink Ack/Nack\n", tbf->tfi, tbf->tlli);
 		tbf->poll_state = GPRS_RLCMAC_POLL_NONE;
+		debug_diagram(tbf->diag, "got DL-ACK");
 
 		rc = gprs_rlcmac_downlink_ack(tbf,
 			ul_control_block->u.Packet_Downlink_Ack_Nack.Ack_Nack_Description.FINAL_ACK_INDICATION,
@@ -427,6 +439,7 @@ int gprs_rlcmac_rcv_control_block(bitvec *rlc_block, uint8_t trx, uint8_t ts,
 				tbf->control_ts = ts;
 				/* schedule uplink assignment */
 				tbf->ul_ass_state = GPRS_RLCMAC_UL_ASS_SEND_ASS;
+				debug_diagram(tbf->diag, "Res. REQ");
 				break;
 			}
 			tfi = tbf->tfi;
@@ -506,6 +519,8 @@ void tbf_timer_cb(void *_tbf)
 		gprs_rlcmac_diag(tbf);
 		/* fall through */
 	case 3193:
+		if (tbf->T == 3193)
+		        debug_diagram(tbf->diag, "T3193 timeout");
 		LOGP(DRLCMAC, LOGL_DEBUG, "TBF will be freed due to timeout\n");
 		/* free TBF */
 		tbf_free(tbf);
@@ -773,6 +788,7 @@ struct msgb *gprs_rlcmac_send_uplink_ack(struct gprs_rlcmac_tbf *tbf,
 		tbf->dir.ul.final_ack_sent = 1;
 	} else
 		tbf->ul_ack_state = GPRS_RLCMAC_UL_ACK_NONE;
+	debug_diagram(tbf->diag, "send UL-ACK");
 
 	return msg;
 }
@@ -961,6 +977,17 @@ int gprs_rlcmac_rcv_data_block_acknowledged(uint8_t trx, uint8_t ts,
 				SEND_ACK_AFTER_FRAMES);
 		}
 		if (tbf->ul_ack_state == GPRS_RLCMAC_UL_ACK_NONE) {
+#ifdef DEBUG_DIAGRAM
+			if (rh->si)
+				debug_diagram(tbf->diag, "sched UL-ACK stall");
+			if (rh->ti)
+				debug_diagram(tbf->diag, "sched UL-ACK TLLI");
+			if (tbf->state == GPRS_RLCMAC_FINISHED)
+				debug_diagram(tbf->diag, "sched UL-ACK CV==0");
+			if ((tbf->dir.ul.rx_counter % SEND_ACK_AFTER_FRAMES) == 0)
+				debug_diagram(tbf->diag, "sched UL-ACK n=%d",
+					tbf->dir.ul.rx_counter);
+#endif
 			/* trigger sending at next RTS */
 			tbf->ul_ack_state = GPRS_RLCMAC_UL_ACK_SEND_ACK;
 		} else {
@@ -1041,6 +1068,7 @@ struct msgb *gprs_rlcmac_send_packet_uplink_assignment(
 	tbf_new_state(new_tbf, GPRS_RLCMAC_FLOW);
 	tbf_assign_control_ts(new_tbf);
 #endif
+	debug_diagram(tbf->diag, "send UL-ASS");
 
 	return msg;
 }
@@ -1483,6 +1511,14 @@ tx_block:
 			tbf->poll_state = GPRS_RLCMAC_POLL_SCHED;
 			tbf->poll_fn = (fn + 13) % 2715648;
 
+#ifdef DEBUG_DIAGRAM
+			debug_diagram(tbf->diag, "poll DL-ACK");
+			if (first_fin_ack)
+				debug_diagram(tbf->diag, "(is first FINAL)");
+			if (rh->fbi)
+				debug_diagram(tbf->diag, "(FBI is set)");
+#endif
+
 			/* set polling in header */
 			rh->rrbp = 0; /* N+13 */
 			rh->s_p = 1; /* Polling */
@@ -1595,8 +1631,10 @@ int gprs_rlcmac_downlink_ack(struct gprs_rlcmac_tbf *tbf, uint8_t final,
 				"but without final ack inidcation\n");
 		} else
 			return 0;
-	} else
+	} else {
 		LOGP(DRLCMACDL, LOGL_DEBUG, "- Final ACK received.\n");
+		debug_diagram(tbf->diag, "got Final ACK");
+	}
 
 	/* check for LLC PDU in the LLC Queue */
 	msg = llc_dequeue(tbf);
@@ -1607,6 +1645,7 @@ int gprs_rlcmac_downlink_ack(struct gprs_rlcmac_tbf *tbf, uint8_t final,
 		LOGP(DRLCMACDL, LOGL_DEBUG, "- No new message, so we "
 			"release.\n");
 		/* start T3193 */
+		debug_diagram(tbf->diag, "start T3193");
 		tbf_timer_start(tbf, 3193, bts->t3193_msec / 1000,
 			(bts->t3193_msec % 1000) * 1000);
 		tbf_new_state(tbf, GPRS_RLCMAC_WAIT_RELEASE);
@@ -1716,6 +1755,7 @@ struct msgb *gprs_rlcmac_send_packet_downlink_assignment(
 		tbf_timer_stop(new_tbf);
 
 	}
+	debug_diagram(tbf->diag, "send DL-ASS");
 
 	return msg;
 }
@@ -1726,6 +1766,7 @@ static void gprs_rlcmac_downlink_assignment(gprs_rlcmac_tbf *tbf, uint8_t poll,
 	struct gprs_rlcmac_bts *bts = gprs_rlcmac_bts;
 	int plen;
 
+	debug_diagram(tbf->diag, "IMM.ASS (PCH)");
 	LOGP(DRLCMAC, LOGL_INFO, "TX: START TFI: %u TLLI: 0x%08x Immediate Assignment Downlink (PCH)\n", tbf->tfi, tbf->tlli);
 	bitvec *immediate_assignment = bitvec_alloc(22); /* without plen */
 	bitvec_unhex(immediate_assignment, "2b2b2b2b2b2b2b2b2b2b2b2b2b2b2b2b2b2b2b2b2b2b");
diff --git a/src/pcu_main.cpp b/src/pcu_main.cpp
index ee6f70c4..142c9f98 100644
--- a/src/pcu_main.cpp
+++ b/src/pcu_main.cpp
@@ -41,6 +41,10 @@ extern struct vty_app_info pcu_vty_info;
 void *tall_pcu_ctx;
 static int quit = 0;
 
+#ifdef DEBUG_DIAGRAM
+extern struct timeval diagram_time;
+#endif
+
 static void print_help()
 {
 	printf( "Some useful options:\n"
@@ -206,6 +210,9 @@ int main(int argc, char *argv[])
 		osmo_gsm_timers_update();
 
 		osmo_select_main(0);
+#ifdef DEBUG_DIAGRAM
+		gettimeofday(&diagram_time, NULL);
+#endif
 	}
 
 	telnet_exit();