[PATCH] osmo-pcu[master]: TBF: log timer invocation source

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.org
Fri Dec 8 14:34:08 UTC 2017


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 <msuraev at sysmocom.de>
Gerrit-Reviewer: Harald Welte <laforge at gnumonks.org>
Gerrit-Reviewer: Jenkins Builder



More information about the gerrit-log mailing list