This is merely a historical archive of years 2008-2021, before the migration to mailman3.
A maintained and still updated list archive can be found at https://lists.osmocom.org/hyperkitty/list/gerrit-log@lists.osmocom.org/.
Max gerrit-no-reply at lists.osmocom.orgReview at https://gerrit.osmocom.org/5208 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. Change-Id: If5f883ae52c469e5158bad24da9904fdc455582f Related: OS#2407 --- M src/bts.cpp M src/tbf.cpp M src/tbf.h M src/tbf_dl.cpp M src/tbf_ul.cpp 5 files changed, 20 insertions(+), 16 deletions(-) git pull ssh://gerrit.osmocom.org:29418/osmo-pcu refs/changes/08/5208/1 diff --git a/src/bts.cpp b/src/bts.cpp index 341c9d4..42bc641 100644 --- a/src/bts.cpp +++ b/src/bts.cpp @@ -548,7 +548,7 @@ 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, "assignment (AGCH)"); + tbf_timer_start(dl_tbf, 0, Tassign_agch, "assignment (AGCH)", __FILE__, __LINE__); return 0; } @@ -681,7 +681,7 @@ 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, "RACH (new UL-TBF)"); + tbf_timer_start(tbf, 3169, m_bts.t3169, 0, "RACH (new UL-TBF)", __FILE__, __LINE__); LOGP(DRLCMAC, LOGL_DEBUG, "%s [UPLINK] START\n", tbf_name(tbf)); LOGP(DRLCMAC, LOGL_DEBUG, "%s RX: [PCU <- BTS] RACH " diff --git a/src/tbf.cpp b/src/tbf.cpp index 7b609c8..5d495c8 100644 --- a/src/tbf.cpp +++ b/src/tbf.cpp @@ -34,6 +34,7 @@ #include <osmocom/core/msgb.h> #include <osmocom/core/talloc.h> #include <osmocom/core/stats.h> +#include <osmocom/core/logging.h> } #include <errno.h> @@ -394,7 +395,7 @@ 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, "allocation (UL-TBF)"); + tbf_timer_start(tbf, 3169, bts->t3169, 0, "allocation (UL-TBF)", __FILE__, __LINE__); tbf->update_ms(tlli, GPRS_RLCMAC_UL_TBF); OSMO_ASSERT(tbf->ms()); @@ -529,14 +530,14 @@ }; void tbf_timer_start(struct gprs_rlcmac_tbf *tbf, unsigned int T, - unsigned int seconds, unsigned int microseconds, const char *reason) + unsigned int seconds, unsigned int microseconds, const char *reason, const char *file, int line) { - LOGPC(DRLCMAC, (T != tbf->T) ? LOGL_ERROR : LOGL_DEBUG, + LOGPSRC(DRLCMAC, (T != tbf->T) ? LOGL_ERROR : LOGL_DEBUG, file, line, "%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 T%u pending", tbf->T); + LOGPSRC(DRLCMAC, LOGL_ERROR, file, line, " while old timer T%u pending", tbf->T); LOGPC(DRLCMAC, (T != tbf->T) ? LOGL_ERROR : LOGL_DEBUG, "\n"); @@ -663,7 +664,8 @@ "- 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, "MAX N3103 reached"); + tbf_timer_start(ul_tbf, 3169, ul_tbf->bts->bts_data()->t3169, 0, "MAX N3103 reached", + __FILE__, __LINE__); return; } /* reschedule UL ack */ @@ -685,7 +687,7 @@ 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, "MAX N3105 reached"); + tbf_timer_start(this, 3195, bts_data()->t3195, 0, "MAX N3105 reached", __FILE__, __LINE__); bts->rlc_ass_failed(); bts->pua_poll_failed(); return; @@ -707,7 +709,7 @@ 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, "MAX N3105 reached"); + tbf_timer_start(this, 3195, bts_data()->t3195, 0, "MAX N3105 reached", __FILE__, __LINE__); bts->rlc_ass_failed(); bts->pda_poll_failed(); return; @@ -733,7 +735,8 @@ 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, "MAX N3105 reached"); + tbf_timer_start(dl_tbf, 3195, dl_tbf->bts_data()->t3195, 0, "MAX N3105 reached", + __FILE__, __LINE__); bts->pkt_dl_ack_nack_poll_failed(); bts->rlc_ack_failed(); return; @@ -1223,7 +1226,7 @@ /* Start Tmr only if it is UL TBF */ if (direction == GPRS_RLCMAC_UL_TBF) - tbf_timer_start(this, 0, Treject_pacch, "reject (PACCH)"); + tbf_timer_start(this, 0, Treject_pacch, "reject (PACCH)", __FILE__, __LINE__); return msg; diff --git a/src/tbf.h b/src/tbf.h index 80249df..6ec1551 100644 --- a/src/tbf.h +++ b/src/tbf.h @@ -330,7 +330,7 @@ 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, const char *reason); + unsigned int seconds, unsigned int microseconds, const char *reason, const char *file, int line); 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 73708f5..9a3c08c 100644 --- a/src/tbf_dl.cpp +++ b/src/tbf_dl.cpp @@ -502,7 +502,7 @@ state_flags |= (1 << GPRS_RLCMAC_FLAG_PACCH); /* start timer */ - tbf_timer_start(this, 0, Tassign_pacch, "assignment (PACCH)"); + tbf_timer_start(this, 0, Tassign_pacch, "assignment (PACCH)", __FILE__, __LINE__); } 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,8 @@ m_tx_counter = 0; /* start timer whenever we send the final block */ if (is_final) - tbf_timer_start(this, 3191, bts_data()->t3191, 0, "final block (DL-TBF)"); + tbf_timer_start(this, 3191, bts_data()->t3191, 0, "final block (DL-TBF)", + __FILE__, __LINE__); clear_poll_timeout_flag(); @@ -1126,7 +1127,7 @@ /* start T3193 */ tbf_timer_start(this, 3193, bts_data()->t3193_msec / 1000, - (bts_data()->t3193_msec % 1000) * 1000, "release (DL-TBF)"); + (bts_data()->t3193_msec % 1000) * 1000, "release (DL-TBF)", __FILE__, __LINE__); /* reset rlc states */ m_tx_counter = 0; diff --git a/src/tbf_ul.cpp b/src/tbf_ul.cpp index 0bbb817..2fd9fcf 100644 --- a/src/tbf_ul.cpp +++ b/src/tbf_ul.cpp @@ -193,7 +193,7 @@ unsigned int block_idx; /* restart T3169 */ - tbf_timer_start(this, 3169, bts_data()->t3169, 0, "acked (data)"); + tbf_timer_start(this, 3169, bts_data()->t3169, 0, "acked (data)", __FILE__, __LINE__); /* Increment RX-counter */ this->m_rx_counter++; -- To view, visit https://gerrit.osmocom.org/5208 To unsubscribe, visit https://gerrit.osmocom.org/settings Gerrit-MessageType: newchange Gerrit-Change-Id: If5f883ae52c469e5158bad24da9904fdc455582f Gerrit-PatchSet: 1 Gerrit-Project: osmo-pcu Gerrit-Branch: master Gerrit-Owner: Max <msuraev at sysmocom.de>