29 Apr
2022
29 Apr
'22
5:11 p.m.
pespin has submitted this change. ( https://gerrit.osmocom.org/c/osmo-bsc/+/27964 )
Change subject: paging: Improve logging
......................................................................
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(-)
Approvals:
Jenkins Builder: Verified
fixeria: Looks good to me, but someone else must approve
laforge: Looks good to me, approved
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++;
}
1 is the latest approved patch-set.
No files were changed between the latest approved patch-set and the submitted one.
--
To view, visit https://gerrit.osmocom.org/c/osmo-bsc/+/27964
To unsubscribe, or for help writing mail filters, visit
https://gerrit.osmocom.org/settings
Gerrit-Project: osmo-bsc
Gerrit-Branch: master
Gerrit-Change-Id: I8a83352d6f2370bafa5acb0caba6b2f352263b5c
Gerrit-Change-Number: 27964
Gerrit-PatchSet: 2
Gerrit-Owner: pespin <pespin(a)sysmocom.de>
Gerrit-Reviewer: Jenkins Builder
Gerrit-Reviewer: fixeria <vyanitskiy(a)sysmocom.de>
Gerrit-Reviewer: laforge <laforge(a)osmocom.org>
Gerrit-Reviewer: pespin <pespin(a)sysmocom.de>
Gerrit-MessageType: merged