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.
This commit is contained in:
Andreas Eversberg 2012-10-07 15:26:00 +02:00
parent 5cae087ae9
commit b83e2a7d5c
4 changed files with 180 additions and 4 deletions

View File

@ -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]);

View File

@ -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);

View File

@ -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");

View File

@ -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();