Hello Jenkins Builder,
I'd like you to reexamine a change. Please visit
https://gerrit.osmocom.org/5208
to look at the new patch set (#2).
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
---
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, 24 insertions(+), 19 deletions(-)
git pull ssh://gerrit.osmocom.org:29418/osmo-pcu refs/changes/08/5208/2
diff --git a/src/bts.cpp b/src/bts.cpp
index 00c2016..4dd5851 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)
- 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;
}
@@ -681,7 +681,7 @@
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);
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 12a335d..0393b6d 100644
--- a/src/tbf.cpp
+++ b/src/tbf.cpp
@@ -35,6 +35,7 @@
#include <osmocom/core/utils.h>
#include <osmocom/core/talloc.h>
#include <osmocom/core/stats.h>
+#include <osmocom/core/logging.h>
}
#include <errno.h>
@@ -403,7 +404,7 @@
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());
@@ -594,17 +595,18 @@
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) {
- LOGP(DRLCMAC, LOGL_ERROR, "%s attempting to start unknown timer
%s [%s]\n",
- tbf_name(this), 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;
- LOGP(DRLCMAC, LOGL_DEBUG, "%s %sstarting timer %s [%s] with %u sec. %u
microsec.\n",
+ 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);
@@ -627,7 +629,7 @@
T[t].cb = cb_T3195;
break;
default:
- LOGP(DRLCMAC, LOGL_ERROR, "%s attempting to set callback for
unknown timer %s [%s]\n",
+ 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);
}
@@ -723,7 +725,7 @@
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;
}
@@ -741,7 +743,7 @@
"- 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 */
@@ -763,7 +765,7 @@
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;
@@ -785,7 +787,7 @@
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;
@@ -811,7 +813,7 @@
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;
@@ -1279,7 +1281,7 @@
/* 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 d0334db..cd52ce0 100644
--- a/src/tbf.h
+++ b/src/tbf.h
@@ -167,6 +167,8 @@
#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);
@@ -198,7 +200,8 @@
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 32b1796..073edd4 100644
--- a/src/tbf_dl.cpp
+++ b/src/tbf_dl.cpp
@@ -502,7 +502,7 @@
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 {
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 @@
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();
@@ -1124,7 +1124,7 @@
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 c2cedc7..7ba0572 100644
--- a/src/tbf_ul.cpp
+++ b/src/tbf_ul.cpp
@@ -193,7 +193,7 @@
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++;
--
To view, visit https://gerrit.osmocom.org/5208
To unsubscribe, visit https://gerrit.osmocom.org/settings
Gerrit-MessageType: newpatchset
Gerrit-Change-Id: If5f883ae52c469e5158bad24da9904fdc455582f
Gerrit-PatchSet: 2
Gerrit-Project: osmo-pcu
Gerrit-Branch: master
Gerrit-Owner: Max <msur...@sysmocom.de>
Gerrit-Reviewer: Harald Welte <lafo...@gnumonks.org>
Gerrit-Reviewer: Jenkins Builder
