diff options
author | Max <msuraev@sysmocom.de> | 2017-12-01 17:40:20 +0100 |
---|---|---|
committer | Harald Welte <laforge@gnumonks.org> | 2017-12-05 18:47:22 +0000 |
commit | cea806e5b9bf7f6c4bdd15520c5914f320fe92f0 (patch) | |
tree | fed34608257183d311f8fc96f629a46045c436f4 /src | |
parent | b4d368b5769e2808cddd15917ef3f06583e920df (diff) |
TBF: expand timer logging
* log timer values
* log start/stop cause
* update test output as necessary
This simplifies debugging issues with TBF timers.
Related: OS#2407
Change-Id: Ib8e537416af9bec5d447356286f44e9e8bbf1b7a
Diffstat (limited to 'src')
-rw-r--r-- | src/bts.cpp | 6 | ||||
-rw-r--r-- | src/tbf.cpp | 33 | ||||
-rw-r--r-- | src/tbf.h | 4 | ||||
-rw-r--r-- | src/tbf_dl.cpp | 8 | ||||
-rw-r--r-- | src/tbf_ul.cpp | 2 |
5 files changed, 27 insertions, 26 deletions
diff --git a/src/bts.cpp b/src/bts.cpp index c3231011..341c9d42 100644 --- a/src/bts.cpp +++ b/src/bts.cpp @@ -548,7 +548,7 @@ int BTS::rcv_imm_ass_cnf(const uint8_t *data, uint32_t fn) LOGP(DRLCMAC, LOGL_DEBUG, "Got IMM.ASS confirm for TLLI=%08x\n", tlli); if (dl_tbf->m_wait_confirm) - tbf_timer_start(dl_tbf, 0, Tassign_agch); + tbf_timer_start(dl_tbf, 0, Tassign_agch, "assignment (AGCH)"); return 0; } @@ -681,7 +681,7 @@ int BTS::rcv_rach(uint16_t ra, uint32_t Fn, int16_t qta, uint8_t is_11bit, tbf->set_ta(ta); tbf->set_state(GPRS_RLCMAC_FLOW); tbf->state_flags |= (1 << GPRS_RLCMAC_FLAG_CCCH); - tbf_timer_start(tbf, 3169, m_bts.t3169, 0); + tbf_timer_start(tbf, 3169, m_bts.t3169, 0, "RACH (new UL-TBF)"); LOGP(DRLCMAC, LOGL_DEBUG, "%s [UPLINK] START\n", tbf_name(tbf)); LOGP(DRLCMAC, LOGL_DEBUG, "%s RX: [PCU <- BTS] RACH " @@ -1036,7 +1036,7 @@ void gprs_rlcmac_pdch::rcv_control_ack(Packet_Control_Acknowledgement_t *packet, } new_tbf->set_state(GPRS_RLCMAC_FLOW); /* stop pending assignment timer */ - new_tbf->stop_timer(); + new_tbf->stop_timer("control acked (DL-TBF)"); if ((new_tbf->state_flags & (1 << GPRS_RLCMAC_FLAG_TO_DL_ASS))) { new_tbf->state_flags &= diff --git a/src/tbf.cpp b/src/tbf.cpp index 831cd971..7b609c84 100644 --- a/src/tbf.cpp +++ b/src/tbf.cpp @@ -394,7 +394,7 @@ gprs_rlcmac_ul_tbf *tbf_alloc_ul(struct gprs_rlcmac_bts *bts, tbf->m_contention_resolution_done = 1; tbf->set_state(GPRS_RLCMAC_ASSIGN); tbf->state_flags |= (1 << GPRS_RLCMAC_FLAG_PACCH); - tbf_timer_start(tbf, 3169, bts->t3169, 0); + tbf_timer_start(tbf, 3169, bts->t3169, 0, "allocation (UL-TBF)"); tbf->update_ms(tlli, GPRS_RLCMAC_UL_TBF); OSMO_ASSERT(tbf->ms()); @@ -464,7 +464,7 @@ void tbf_free(struct gprs_rlcmac_tbf *tbf) tbf_name(tbf), get_value_string(gprs_rlcmac_tbf_dl_ass_state_names, tbf->dl_ass_state)); - tbf->stop_timer(); + tbf->stop_timer("freeing TBF"); /* TODO: Could/Should generate bssgp_tx_llc_discarded */ tbf_unlink_pdch(tbf); llist_del(&tbf->list()); @@ -529,13 +529,14 @@ const char *gprs_rlcmac_tbf::tbf_state_name[] = { }; void tbf_timer_start(struct gprs_rlcmac_tbf *tbf, unsigned int T, - unsigned int seconds, unsigned int microseconds) + unsigned int seconds, unsigned int microseconds, const char *reason) { - LOGPC(DRLCMAC, (T != tbf->T) ? LOGL_ERROR : LOGL_DEBUG, "%s %sstarting timer %u.", - tbf_name(tbf), osmo_timer_pending(&tbf->timer) ? "re" : "", T); + LOGPC(DRLCMAC, (T != tbf->T) ? LOGL_ERROR : LOGL_DEBUG, + "%s %sstarting timer T%u [%s] with %u sec. %u microsec.", + tbf_name(tbf), osmo_timer_pending(&tbf->timer) ? "re" : "", T, reason, seconds, microseconds); if (T != tbf->T && osmo_timer_pending(&tbf->timer)) - LOGPC(DRLCMAC, LOGL_ERROR, " while old timer %u pending", tbf->T); + LOGPC(DRLCMAC, LOGL_ERROR, " while old timer T%u pending", tbf->T); LOGPC(DRLCMAC, (T != tbf->T) ? LOGL_ERROR : LOGL_DEBUG, "\n"); @@ -551,14 +552,14 @@ void tbf_timer_start(struct gprs_rlcmac_tbf *tbf, unsigned int T, void gprs_rlcmac_tbf::stop_t3191() { - return stop_timer(); + return stop_timer("T3191"); } -void gprs_rlcmac_tbf::stop_timer() +void gprs_rlcmac_tbf::stop_timer(const char *reason) { if (osmo_timer_pending(&timer)) { - LOGP(DRLCMAC, LOGL_DEBUG, "%s stopping timer %u.\n", - tbf_name(this), T); + LOGP(DRLCMAC, LOGL_DEBUG, "%s stopping timer T%u [%s]\n", + tbf_name(this), T, reason); osmo_timer_del(&timer); } } @@ -662,7 +663,7 @@ void gprs_rlcmac_tbf::poll_timeout() "- N3103 exceeded\n"); bts->pkt_ul_ack_nack_poll_failed(); ul_tbf->set_state(GPRS_RLCMAC_RELEASING); - tbf_timer_start(ul_tbf, 3169, ul_tbf->bts->bts_data()->t3169, 0); + tbf_timer_start(ul_tbf, 3169, ul_tbf->bts->bts_data()->t3169, 0, "MAX N3103 reached"); return; } /* reschedule UL ack */ @@ -684,7 +685,7 @@ void gprs_rlcmac_tbf::poll_timeout() if (n3105 == bts_data()->n3105) { LOGP(DRLCMAC, LOGL_NOTICE, "- N3105 exceeded\n"); set_state(GPRS_RLCMAC_RELEASING); - tbf_timer_start(this, 3195, bts_data()->t3195, 0); + tbf_timer_start(this, 3195, bts_data()->t3195, 0, "MAX N3105 reached"); bts->rlc_ass_failed(); bts->pua_poll_failed(); return; @@ -706,7 +707,7 @@ void gprs_rlcmac_tbf::poll_timeout() if (n3105 == bts->bts_data()->n3105) { LOGP(DRLCMAC, LOGL_NOTICE, "- N3105 exceeded\n"); set_state(GPRS_RLCMAC_RELEASING); - tbf_timer_start(this, 3195, bts_data()->t3195, 0); + tbf_timer_start(this, 3195, bts_data()->t3195, 0, "MAX N3105 reached"); bts->rlc_ass_failed(); bts->pda_poll_failed(); return; @@ -732,7 +733,7 @@ void gprs_rlcmac_tbf::poll_timeout() if (dl_tbf->n3105 == dl_tbf->bts->bts_data()->n3105) { LOGP(DRLCMAC, LOGL_NOTICE, "- N3105 exceeded\n"); dl_tbf->set_state(GPRS_RLCMAC_RELEASING); - tbf_timer_start(dl_tbf, 3195, dl_tbf->bts_data()->t3195, 0); + tbf_timer_start(dl_tbf, 3195, dl_tbf->bts_data()->t3195, 0, "MAX N3105 reached"); bts->pkt_dl_ack_nack_poll_failed(); bts->rlc_ack_failed(); return; @@ -1192,7 +1193,7 @@ struct msgb *gprs_rlcmac_tbf::create_dl_ass(uint32_t fn, uint8_t ts) new_dl_tbf->set_state(GPRS_RLCMAC_FLOW); tbf_assign_control_ts(new_dl_tbf); /* stop pending assignment timer */ - new_dl_tbf->stop_timer(); + new_dl_tbf->stop_timer("assignment (DL-TBF)"); } @@ -1222,7 +1223,7 @@ struct msgb *gprs_rlcmac_tbf::create_packet_access_reject() /* Start Tmr only if it is UL TBF */ if (direction == GPRS_RLCMAC_UL_TBF) - tbf_timer_start(this, 0, Treject_pacch); + tbf_timer_start(this, 0, Treject_pacch, "reject (PACCH)"); return msg; @@ -174,7 +174,7 @@ struct gprs_rlcmac_tbf { int update(); void handle_timeout(); - void stop_timer(); + void stop_timer(const char *reason); void stop_t3191(); int establish_dl_tbf_on_pacch(); @@ -330,7 +330,7 @@ struct gprs_rlcmac_ul_tbf *handle_tbf_reject(struct gprs_rlcmac_bts *bts, int tbf_assign_control_ts(struct gprs_rlcmac_tbf *tbf); void tbf_timer_start(struct gprs_rlcmac_tbf *tbf, unsigned int T, - unsigned int seconds, unsigned int microseconds); + unsigned int seconds, unsigned int microseconds, const char *reason); inline bool gprs_rlcmac_tbf::state_is(enum gprs_rlcmac_tbf_state rhs) const { diff --git a/src/tbf_dl.cpp b/src/tbf_dl.cpp index 3d278835..73708f55 100644 --- a/src/tbf_dl.cpp +++ b/src/tbf_dl.cpp @@ -488,7 +488,7 @@ struct msgb *gprs_rlcmac_dl_tbf::create_dl_acked_block(uint32_t fn, uint8_t ts) void gprs_rlcmac_dl_tbf::trigger_ass(struct gprs_rlcmac_tbf *old_tbf) { /* stop pending timer */ - stop_timer(); + stop_timer("assignment (DL-TBF)"); /* check for downlink tbf: */ if (old_tbf) { @@ -502,7 +502,7 @@ void gprs_rlcmac_dl_tbf::trigger_ass(struct gprs_rlcmac_tbf *old_tbf) state_flags |= (1 << GPRS_RLCMAC_FLAG_PACCH); /* start timer */ - tbf_timer_start(this, 0, Tassign_pacch); + tbf_timer_start(this, 0, Tassign_pacch, "assignment (PACCH)"); } else { LOGP(DRLCMACDL, LOGL_DEBUG, "Send dowlink assignment for %s on PCH, no TBF exist (IMSI=%s)\n", tbf_name(this), imsi()); @@ -861,7 +861,7 @@ struct msgb *gprs_rlcmac_dl_tbf::create_dl_acked_block( m_tx_counter = 0; /* start timer whenever we send the final block */ if (is_final) - tbf_timer_start(this, 3191, bts_data()->t3191, 0); + tbf_timer_start(this, 3191, bts_data()->t3191, 0, "final block (DL-TBF)"); clear_poll_timeout_flag(); @@ -1126,7 +1126,7 @@ int gprs_rlcmac_dl_tbf::release() /* start T3193 */ tbf_timer_start(this, 3193, bts_data()->t3193_msec / 1000, - (bts_data()->t3193_msec % 1000) * 1000); + (bts_data()->t3193_msec % 1000) * 1000, "release (DL-TBF)"); /* reset rlc states */ m_tx_counter = 0; diff --git a/src/tbf_ul.cpp b/src/tbf_ul.cpp index 81d3b24a..0bbb817d 100644 --- a/src/tbf_ul.cpp +++ b/src/tbf_ul.cpp @@ -193,7 +193,7 @@ int gprs_rlcmac_ul_tbf::rcv_data_block_acknowledged( unsigned int block_idx; /* restart T3169 */ - tbf_timer_start(this, 3169, bts_data()->t3169, 0); + tbf_timer_start(this, 3169, bts_data()->t3169, 0, "acked (data)"); /* Increment RX-counter */ this->m_rx_counter++; |