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.
diff --git a/src/gprs_rlcmac.cpp b/src/gprs_rlcmac.cpp
index fcd92c6..b5e0f35 100644
--- a/src/gprs_rlcmac.cpp
+++ b/src/gprs_rlcmac.cpp
@@ -89,6 +89,90 @@
};
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;
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 @@
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 @@
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 @@
{
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 @@
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 1900d89..c67a68b 100644
--- a/src/gprs_rlcmac.h
+++ b/src/gprs_rlcmac.h
@@ -31,6 +31,9 @@
}
#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 @@
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 @@
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 edc324b..776c416 100644
--- a/src/gprs_rlcmac_data.cpp
+++ b/src/gprs_rlcmac_data.cpp
@@ -109,6 +109,7 @@
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 @@
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 @@
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 @@
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 @@
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 @@
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 @@
/* 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 @@
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 @@
/* 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 @@
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 @@
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 @@
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 @@
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 @@
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 @@
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 @@
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 @@
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 @@
"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 @@
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 @@
tbf_timer_stop(new_tbf);
}
+ debug_diagram(tbf->diag, "send DL-ASS");
return msg;
}
@@ -1726,6 +1766,7 @@
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 ee6f70c..142c9f9 100644
--- a/src/pcu_main.cpp
+++ b/src/pcu_main.cpp
@@ -41,6 +41,10 @@
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 @@
osmo_gsm_timers_update();
osmo_select_main(0);
+#ifdef DEBUG_DIAGRAM
+ gettimeofday(&diagram_time, NULL);
+#endif
}
telnet_exit();