paging: Improve logging

Change-Id: I3186f841623cad8ed3296ac4d541e5cf4701132d
This commit is contained in:
Pau Espin 2022-05-05 17:19:32 +02:00 committed by pespin
parent f4dca1b53f
commit 38db714588
2 changed files with 144 additions and 134 deletions

View File

@ -262,7 +262,8 @@ static void paging_handle_pending_requests(struct gsm_bts_paging_state *paging_b
struct timespec tdiff; struct timespec tdiff;
timespecsub(&retrans_ts, &now, &tdiff); timespecsub(&retrans_ts, &now, &tdiff);
LOG_PAGING_BTS(request, request->bts, DPAG, LOGL_DEBUG, LOG_PAGING_BTS(request, request->bts, DPAG, LOGL_DEBUG,
"Paging delayed: retransmission happens later\n"); "Paging delayed: retransmission happens in %lld.%06lds\n",
(long long)tdiff.tv_sec, tdiff.tv_nsec / 1000);
osmo_timer_schedule(&paging_bts->work_timer, tdiff.tv_sec, tdiff.tv_nsec / 1000); osmo_timer_schedule(&paging_bts->work_timer, tdiff.tv_sec, tdiff.tv_nsec / 1000);
return; return;
} }
@ -283,8 +284,10 @@ static void paging_handle_pending_requests(struct gsm_bts_paging_state *paging_b
/* Once done iterating, prepare next scheduling: */ /* Once done iterating, prepare next scheduling: */
sched_next_iter: sched_next_iter:
LOG_BTS(bts, DPAG, LOGL_DEBUG, "Paged %u subscribers during last iteration. Scheduling next batch (available_slots=%u)\n", LOG_BTS(bts, DPAG, LOGL_DEBUG, "Paged %u subscribers during last iteration. "
num_paged, paging_bts->available_slots); "Scheduling next batch in %lld.%06lds (available_slots=%u)\n",
num_paged, (long long)initial_period.tv_sec, initial_period.tv_nsec / 1000,
paging_bts->available_slots);
osmo_timer_schedule(&paging_bts->work_timer, initial_period.tv_sec, initial_period.tv_nsec / 1000); osmo_timer_schedule(&paging_bts->work_timer, initial_period.tv_sec, initial_period.tv_nsec / 1000);
} }
@ -455,15 +458,19 @@ static int _paging_request(const struct bsc_paging_params *params, struct gsm_bt
* which is a longer period. * which is a longer period.
* Let's recaculate the time to adapt it to initial_period: */ * Let's recaculate the time to adapt it to initial_period: */
struct timespec now, elapsed, tdiff; struct timespec now, elapsed, tdiff;
struct gsm_paging_request *first_retrans_req;
osmo_clock_gettime(CLOCK_MONOTONIC, &now); osmo_clock_gettime(CLOCK_MONOTONIC, &now);
/* This is what used to be the first req (retrans state) in the queue: */ /* This is what used to be the first req (retrans state) in the queue: */
req = llist_entry(req->entry.next, struct gsm_paging_request, entry); first_retrans_req = llist_entry(req->entry.next, struct gsm_paging_request, entry);
timespecsub(&now, &req->last_attempt_ts, &elapsed); timespecsub(&now, &first_retrans_req->last_attempt_ts, &elapsed);
if (timespeccmp(&elapsed, &initial_period, <)) { if (timespeccmp(&elapsed, &initial_period, <)) {
timespecsub(&initial_period, &elapsed, &tdiff); timespecsub(&initial_period, &elapsed, &tdiff);
} else { } else {
tdiff = (struct timespec){.tv_sec = 0, .tv_nsec = 0 }; tdiff = (struct timespec){.tv_sec = 0, .tv_nsec = 0 };
} }
LOG_PAGING_BTS(req, req->bts, DPAG, LOGL_DEBUG,
"New req arrived: re-scheduling next batch in %lld.%06lds\n",
(long long)tdiff.tv_sec, tdiff.tv_nsec / 1000);
osmo_timer_schedule(&bts_entry->work_timer, tdiff.tv_sec, tdiff.tv_nsec / 1000); osmo_timer_schedule(&bts_entry->work_timer, tdiff.tv_sec, tdiff.tv_nsec / 1000);
} /* else: worker is already ongoing submitting initial requests, nothing do be done */ } /* else: worker is already ongoing submitting initial requests, nothing do be done */

File diff suppressed because it is too large Load Diff