aboutsummaryrefslogtreecommitdiffstats
diff options
context:
space:
mode:
Diffstat
-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 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();
generated by cgit v1.2.3 (git 2.25.1) at 2024-04-26 19:20:53 +0000