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.
-
pespin