From 467f633b165ed2d439bb54d4ae42cdc341ea81b3 Mon Sep 17 00:00:00 2001 From: Max Date: Wed, 20 Dec 2017 18:13:29 +0100 Subject: [PATCH] TBF: log timer invocation source When troubleshooting TBF timers we're not only interested in timer duration but also in the code which triggered it. Let's use LOGPSRC to log it: wrap t_start() in a macro for convenience. Change-Id: If5f883ae52c469e5158bad24da9904fdc455582f Related: OS#2407 --- src/bts.cpp | 4 ++-- src/tbf.cpp | 35 +++++++++++++++++++---------------- src/tbf.h | 5 ++++- src/tbf_dl.cpp | 6 +++--- src/tbf_ul.cpp | 2 +- 5 files changed, 29 insertions(+), 23 deletions(-) diff --git a/src/bts.cpp b/src/bts.cpp index d0ba7685..4bc792a5 100644 --- a/src/bts.cpp +++ b/src/bts.cpp @@ -554,7 +554,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) - dl_tbf->t_start(T0, 0, T_ASS_AGCH_USEC, "assignment (AGCH)", true); + T_START(dl_tbf, T0, 0, T_ASS_AGCH_USEC, "assignment (AGCH)", true); return 0; } @@ -687,7 +687,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->t_start(T3169, m_bts.t3169, 0, "RACH (new UL-TBF)", true); + T_START(tbf, T3169, m_bts.t3169, 0, "RACH (new UL-TBF)", true); LOGPTBF(tbf, LOGL_DEBUG, "[UPLINK] START\n"); LOGPTBF(tbf, LOGL_DEBUG, "RX: [PCU <- BTS] RACH " "qbit-ta=%d ra=0x%02x, Fn=%d " diff --git a/src/tbf.cpp b/src/tbf.cpp index ea27597c..520f6c45 100644 --- a/src/tbf.cpp +++ b/src/tbf.cpp @@ -35,6 +35,7 @@ extern "C" { #include #include #include +#include } #include @@ -403,7 +404,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->t_start(T3169, bts->t3169, 0, "allocation (UL-TBF)", true); + T_START(tbf, T3169, bts->t3169, 0, "allocation (UL-TBF)", true); tbf->update_ms(tlli, GPRS_RLCMAC_UL_TBF); OSMO_ASSERT(tbf->ms()); @@ -544,10 +545,10 @@ void gprs_rlcmac_tbf::t_stop(enum tbf_timers t, const char *reason) get_value_string(tbf_timers_names, t), reason); } - if (osmo_timer_pending(&T31[t])) { + if (osmo_timer_pending(&T[t])) { LOGPTBF(this, LOGL_DEBUG, "stopping timer %s [%s]\n", get_value_string(tbf_timers_names, t), reason); - osmo_timer_del(&T31[t]); + osmo_timer_del(&T[t]); } } @@ -593,18 +594,20 @@ T_CBACK(T3191, true) T_CBACK(T3193, false) T_CBACK(T3195, true) -void gprs_rlcmac_tbf::t_start(enum tbf_timers t, uint32_t sec, uint32_t microsec, const char *reason, bool force) +void gprs_rlcmac_tbf::t_start(enum tbf_timers t, uint32_t sec, uint32_t microsec, const char *reason, bool force, + const char *file, unsigned line) { if (t >= T_MAX) { - LOGPTBF(this, LOGL_ERROR, "attempting to start unknown timer %s [%s]\n", - get_value_string(tbf_timers_names, t), reason); + LOGPSRC(DRLCMAC, LOGL_ERROR, file, line, "%s attempting to start unknown timer %s [%s]\n", + tbf_name(this), get_value_string(tbf_timers_names, t), reason); } if (!force && osmo_timer_pending(&T[t])) return; - LOGPTBF(this, LOGL_DEBUG, "%sstarting timer %s [%s] with %u sec. %u microsec.\n", - osmo_timer_pending(&T[t]) ? "re" : "", get_value_string(tbf_timers_names, t), reason, sec, microsec); + LOGPSRC(DRLCMAC, LOGL_DEBUG, file, line, "%s %sstarting timer %s [%s] with %u sec. %u microsec.\n", + tbf_name(this), osmo_timer_pending(&T[t]) ? "re" : "", + get_value_string(tbf_timers_names, t), reason, sec, microsec); T[t].data = this; @@ -625,8 +628,8 @@ void gprs_rlcmac_tbf::t_start(enum tbf_timers t, uint32_t sec, uint32_t microsec T[t].cb = cb_T3195; break; default: - LOGPTBF(this, LOGL_ERROR, "attempting to set callback for unknown timer %s [%s]\n", - get_value_string(tbf_timers_names, t), reason); + LOGPSRC(DRLCMAC, LOGL_ERROR, file, line, "%s attempting to set callback for unknown timer %s [%s]\n", + tbf_name(this), get_value_string(tbf_timers_names, t), reason); } osmo_timer_schedule(&T[t], sec, microsec); @@ -719,7 +722,7 @@ void gprs_rlcmac_tbf::poll_timeout() if (m_n3101 == bts->bts_data()->n3101) { LOGP(DRLCMAC, LOGL_NOTICE, " N3101 exceeded MAX (%u)\n", bts->bts_data()->n3101); set_state(GPRS_RLCMAC_RELEASING); - t_start(T3169, bts->bts_data()->t3169, 0, "MAX N3101 reached", false); + T_START(this, T3169, bts->bts_data()->t3169, 0, "MAX N3101 reached", false); return; } @@ -737,7 +740,7 @@ void gprs_rlcmac_tbf::poll_timeout() "- N3103 exceeded\n"); bts->pkt_ul_ack_nack_poll_failed(); ul_tbf->set_state(GPRS_RLCMAC_RELEASING); - ul_tbf->t_start(T3169, ul_tbf->bts->bts_data()->t3169, 0, "MAX N3103 reached", false); + T_START(ul_tbf, T3169, ul_tbf->bts->bts_data()->t3169, 0, "MAX N3103 reached", false); return; } /* reschedule UL ack */ @@ -759,7 +762,7 @@ void gprs_rlcmac_tbf::poll_timeout() if (n3105 == bts_data()->n3105) { LOGP(DRLCMAC, LOGL_NOTICE, "- N3105 exceeded\n"); set_state(GPRS_RLCMAC_RELEASING); - t_start(T3195, bts_data()->t3195, 0, "MAX N3105 reached", true); + T_START(this, T3195, bts_data()->t3195, 0, "MAX N3105 reached", true); bts->rlc_ass_failed(); bts->pua_poll_failed(); return; @@ -781,7 +784,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); - t_start(T3195, bts_data()->t3195, 0, "MAX N3105 reached", true); + T_START(this, T3195, bts_data()->t3195, 0, "MAX N3105 reached", true); bts->rlc_ass_failed(); bts->pda_poll_failed(); return; @@ -807,7 +810,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); - dl_tbf->t_start(T3195, dl_tbf->bts_data()->t3195, 0, "MAX N3105 reached", true); + T_START(dl_tbf, T3195, dl_tbf->bts_data()->t3195, 0, "MAX N3105 reached", true); bts->pkt_dl_ack_nack_poll_failed(); bts->rlc_ack_failed(); return; @@ -1266,7 +1269,7 @@ struct msgb *gprs_rlcmac_tbf::create_packet_access_reject() /* Start Tmr only if it is UL TBF */ if (direction == GPRS_RLCMAC_UL_TBF) - t_start(T0, 0, T_REJ_PACCH_USEC, "reject (PACCH)", true); + T_START(this, T0, 0, T_REJ_PACCH_USEC, "reject (PACCH)", true); return msg; diff --git a/src/tbf.h b/src/tbf.h index 88f5d6a1..40ed9742 100644 --- a/src/tbf.h +++ b/src/tbf.h @@ -169,6 +169,8 @@ enum tbf_timers { #define GPRS_RLCMAC_FLAG_TO_DL_ASS 7 #define GPRS_RLCMAC_FLAG_TO_MASK 0xf0 /* timeout bits */ +#define T_START(tbf, t, sec, usec, r, f) tbf->t_start(t, sec, usec, r, f, __FILE__, __LINE__) + struct gprs_rlcmac_tbf { gprs_rlcmac_tbf(BTS *bts_, gprs_rlcmac_tbf_direction dir); @@ -200,7 +202,8 @@ struct gprs_rlcmac_tbf { void stop_timers(const char *reason); bool timers_pending(enum tbf_timers t); void t_stop(enum tbf_timers t, const char *reason); - void t_start(enum tbf_timers t, uint32_t sec, uint32_t microsec, const char *reason, bool force); + void t_start(enum tbf_timers t, uint32_t sec, uint32_t microsec, const char *reason, bool force, + const char *file, unsigned line); int establish_dl_tbf_on_pacch(); int check_polling(uint32_t fn, uint8_t ts, diff --git a/src/tbf_dl.cpp b/src/tbf_dl.cpp index 33eb75b3..84f61667 100644 --- a/src/tbf_dl.cpp +++ b/src/tbf_dl.cpp @@ -498,7 +498,7 @@ void gprs_rlcmac_dl_tbf::trigger_ass(struct gprs_rlcmac_tbf *old_tbf) state_flags |= (1 << GPRS_RLCMAC_FLAG_PACCH); /* start timer */ - t_start(T0, T_ASS_PACCH_SEC, 0, "assignment (PACCH)", true); + T_START(this, T0, T_ASS_PACCH_SEC, 0, "assignment (PACCH)", true); } else { LOGPTBFDL(this, LOGL_DEBUG, "Send dowlink assignment on PCH, no TBF exist (IMSI=%s)\n", imsi()); @@ -854,7 +854,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) - t_start(T3191, bts_data()->t3191, 0, "final block (DL-TBF)", true); + T_START(this, T3191, bts_data()->t3191, 0, "final block (DL-TBF)", true); clear_poll_timeout_flag(); @@ -1116,7 +1116,7 @@ int gprs_rlcmac_dl_tbf::release() set_state(GPRS_RLCMAC_WAIT_RELEASE); /* start T3193 */ - t_start(T3193, bts_data()->t3193_msec / 1000, (bts_data()->t3193_msec % 1000) * 1000, + T_START(this, T3193, bts_data()->t3193_msec / 1000, (bts_data()->t3193_msec % 1000) * 1000, "release (DL-TBF)", true); /* reset rlc states */ diff --git a/src/tbf_ul.cpp b/src/tbf_ul.cpp index 8e4e57e8..45de7cdf 100644 --- a/src/tbf_ul.cpp +++ b/src/tbf_ul.cpp @@ -191,7 +191,7 @@ int gprs_rlcmac_ul_tbf::rcv_data_block_acknowledged( unsigned int block_idx; /* restart T3169 */ - t_start(T3169, bts_data()->t3169, 0, "acked (data)", true); + T_START(this, T3169, bts_data()->t3169, 0, "acked (data)", true); /* Increment RX-counter */ this->m_rx_counter++;