Review 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 <[email protected]>
