aboutsummaryrefslogtreecommitdiffstats
diff options
context:
space:
mode:
authorAndreas Eversberg <jolly@eversberg.eu>2012-10-07 15:26:00 +0200
committerAndreas Eversberg <jolly@eversberg.eu>2012-12-18 10:02:20 +0100
commitb83e2a7d5cae302fb33ad56fa6dbad7906165909 (patch)
treed398de81ccc921a64076baf0ca15202477b39594
parent5cae087ae9ed58910af69e9869b5dca4c0234628 (diff)
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.
-rw-r--r--src/gprs_rlcmac.cpp114
-rw-r--r--src/gprs_rlcmac.h14
-rw-r--r--src/gprs_rlcmac_data.cpp49
-rw-r--r--src/pcu_main.cpp7
4 files changed, 180 insertions, 4 deletions
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 @@ 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 1900d89..c67a68b 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 edc324b..776c416 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 ee6f70c..142c9f9 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();