paging: Improve logging

Change-Id: I8a83352d6f2370bafa5acb0caba6b2f352263b5c
---
M include/osmocom/bsc/paging.h
M src/osmo-bsc/paging.c
2 files changed, 28 insertions(+), 15 deletions(-)

diff --git a/include/osmocom/bsc/paging.h b/include/osmocom/bsc/paging.h
index d9fd501..8d5c9ac 100644
--- a/include/osmocom/bsc/paging.h
+++ b/include/osmocom/bsc/paging.h
@@ -33,14 +33,14 @@
 struct bsc_msc_data;
 
 #define LOG_PAGING(PARAMS, SUBSYS, LEVEL, fmt, args...) \
-	LOGP(SUBSYS, LEVEL, "(msc%d) Paging%s: %s: " fmt, \
+	LOGP(SUBSYS, LEVEL, "(msc=%d) Paging%s: %s: " fmt, \
 	     (PARAMS)->msc ? (PARAMS)->msc->nr : -1, \
 	     (PARAMS)->reason == BSC_PAGING_FOR_LCS ? " for LCS" : "", \
 	     bsc_subscr_name((PARAMS)->bsub), \
 	     ##args)
 
 #define LOG_PAGING_BTS(PARAMS, BTS, SUBSYS, LEVEL, fmt, args...) \
-	LOG_PAGING(PARAMS, SUBSYS, LEVEL, "(bts%u) " fmt, (BTS) ? (BTS)->nr : 255, ##args)
+	LOG_PAGING(PARAMS, SUBSYS, LEVEL, "(bts=%u) " fmt, (BTS) ? (BTS)->nr : 255, ##args)
 
 #define BSUB_USE_PAGING_START "paging-start"
 #define BSUB_USE_PAGING_REQUEST "paging-req"
diff --git a/src/osmo-bsc/paging.c b/src/osmo-bsc/paging.c
index 24a3582..993e5df 100644
--- a/src/osmo-bsc/paging.c
+++ b/src/osmo-bsc/paging.c
@@ -94,9 +94,9 @@
 
 	log_set_context(LOG_CTX_BSC_SUBSCR, request->bsub);
 
-	LOG_BTS(bts, DPAG, LOGL_INFO, "Going to send paging commands: %s"
-		" for ch. type %d (attempt %d)\n", bsc_subscr_name(request->bsub),
-		request->chan_type, request->attempts);
+	LOG_PAGING_BTS(request, bts, DPAG, LOGL_INFO,
+		       "Going to send paging command for ch. type %d (attempt %d)\n",
+		       request->chan_type, request->attempts);
 
 	if (request->bsub->tmsi == GSM_RESERVED_TMSI) {
 		mi = (struct osmo_mobile_identity){
@@ -130,7 +130,11 @@
 {
 	struct gsm_bts_paging_state *paging_bts_st = data;
 	struct gsm_bts *bts = paging_bts_st->bts;
-	paging_bts_st->available_slots = paging_estimate_available_slots(bts, bts->ccch_load_ind_period * 2);
+	uint16_t estimated_slots = paging_estimate_available_slots(bts, bts->ccch_load_ind_period * 2);
+	LOG_BTS(bts, DPAG, LOGL_INFO,
+		"Timeout waiting for CCCH Load Indication, assuming BTS is below Load Threshold (available_slots %u -> %u)\n",
+		paging_bts_st->available_slots, estimated_slots);
+	paging_bts_st->available_slots = estimated_slots;
 	paging_schedule_if_needed(paging_bts_st);
 	osmo_timer_schedule(&bts->paging.credit_timer, bts->ccch_load_ind_period * 2, 0);
 }
@@ -226,8 +230,11 @@
 		/* We run out of available slots. Wait until next CCCH Load Ind
 		 * arrives or credit_timer triggers to keep processing requests.
 		 */
-		if (paging_bts->available_slots == 0)
+		if (paging_bts->available_slots == 0) {
+			LOG_PAGING_BTS(request, request->bts, DPAG, LOGL_INFO,
+				       "Paging delayed: waiting for available slots at BTS\n");
 			return;
+		}
 
 		/* we need to determine the number of free channels */
 		if (paging_bts->free_chans_need != -1 &&
@@ -246,6 +253,8 @@
 			if (timespeccmp(&now, &retrans_ts, <)) {
 				struct timespec tdiff;
 				timespecsub(&retrans_ts, &now, &tdiff);
+				LOG_PAGING_BTS(request, request->bts, DPAG, LOGL_DEBUG,
+					"Paging delayed: retransmission happens later\n");
 				osmo_timer_schedule(&paging_bts->work_timer, tdiff.tv_sec, tdiff.tv_nsec / 1000);
 				return;
 			}
@@ -266,6 +275,8 @@
 
 	/* Once done iterating, prepare next scheduling: */
 sched_next_iter:
+	LOG_BTS(bts, DPAG, LOGL_DEBUG, "Paged %u subscribers during last iteration. Scheduling next batch (available_slots=%u)\n",
+		num_paged, paging_bts->available_slots);
 	osmo_timer_schedule(&paging_bts->work_timer, initial_period.tv_sec, initial_period.tv_nsec / 1000);
 }
 
@@ -302,8 +313,7 @@
 
 	log_set_context(LOG_CTX_BSC_SUBSCR, req->bsub);
 
-	LOGP(DPAG, LOGL_INFO, "T3113 expired for request %p (%s)\n",
-	     req, bsc_subscr_name(req->bsub));
+	 LOG_PAGING_BTS(req, req->bts, DPAG, LOGL_INFO, "T3113 expired\n");
 
 	/* must be destroyed before calling cbfn, to prevent double free */
 	rate_ctr_inc(rate_ctr_group_get_ctr(req->bts->bts_ctrs, BTS_CTR_PAGING_EXPIRED));
@@ -320,9 +330,10 @@
 }
 
 #define GSM51_MFRAME_DURATION_us (51 * GSM_TDMA_FN_DURATION_uS) /* 235365 us */
-static unsigned int calculate_timer_3113(struct gsm_bts *bts)
+static unsigned int calculate_timer_3113(struct gsm_paging_request *req)
 {
 	unsigned int to_us, to;
+	struct gsm_bts *bts = req->bts;
 	struct osmo_tdef *d = osmo_tdef_get_entry(bts->network->T_defs, 3113);
 	unsigned int rach_max_trans, rach_tx_integer, bs_pa_mfrms;
 
@@ -349,7 +360,7 @@
 
 	/* ceiling in seconds + extra time */
 	to = (to_us + 999999) / 1000000 + d->val;
-	LOG_BTS(bts, DPAG, LOGL_DEBUG, "Paging request: T3113 expires in %u seconds\n", to);
+	LOG_PAGING_BTS(req, bts, DPAG, LOGL_DEBUG, "Paging request: T3113 expires in %u seconds\n", to);
 	return to;
 }
 
@@ -403,7 +414,7 @@
 	else/* Add in the middle of the list after last_initial_req */
 		__llist_add(&req->entry, &last_initial_req->entry, last_initial_req->entry.next);
 
-	t3113_timeout_s = calculate_timer_3113(bts);
+	t3113_timeout_s = calculate_timer_3113(req);
 	osmo_timer_schedule(&req->T3113, t3113_timeout_s, 0);
 	paging_schedule_if_needed(bts_entry);
 
@@ -453,7 +464,7 @@
 			continue;
 		*msc_p = req->msc;
 		*reason_p = req->reason;
-		LOG_BTS(bts, DPAG, LOGL_DEBUG, "Stop paging %s\n", bsc_subscr_name(bsub));
+		LOG_PAGING_BTS(req, bts, DPAG, LOGL_DEBUG, "Stop paging\n");
 		paging_remove_request(&bts->paging, req);
 		return 1;
 	}
@@ -519,7 +530,7 @@
 				continue;
 			if (!(req->reason & reasons))
 				continue;
-			LOG_BTS(bts, DPAG, LOGL_DEBUG, "Cancel paging %s\n", bsc_subscr_name(bsub));
+			LOG_PAGING_BTS(req, bts, DPAG, LOGL_DEBUG, "Cancel paging\n");
 			paging_remove_request(&bts->paging, req);
 			count++;
 		}
@@ -530,6 +541,8 @@
 /*! Update the BTS paging buffer slots on given BTS */
 void paging_update_buffer_space(struct gsm_bts *bts, uint16_t free_slots)
 {
+	LOG_BTS(bts, DPAG, LOGL_DEBUG, "Rx CCCH Load Indication from BTS (available_slots %u -> %u)\n",
+		bts->paging.available_slots, free_slots);
 	bts->paging.available_slots = free_slots;
 	paging_schedule_if_needed(&bts->paging);
 	/* Re-arm credit_timer */
@@ -558,7 +571,7 @@
 		if (msc && req->msc != msc)
 			continue;
 		/* now give up the data structure */
-		LOG_BTS(bts, DPAG, LOGL_DEBUG, "Stop paging %s (flush)\n", bsc_subscr_name(req->bsub));
+		LOG_PAGING_BTS(req, bts, DPAG, LOGL_DEBUG, "Stop paging (flush)\n");
 		paging_remove_request(&bts->paging, req);
 		num_cancelled++;
 	}

