From: Arran Cudbard-Bell Date: Sat, 14 Dec 2019 06:49:39 +0000 (+0700) Subject: Rework time tracking so that it no longer uses an explicit tracking list X-Git-Url: http://git.ipfire.org/cgi-bin/gitweb.cgi?a=commitdiff_plain;h=a72607264ab1ffbf037fc68620dd389ac21dada2;p=thirdparty%2Ffreeradius-server.git Rework time tracking so that it no longer uses an explicit tracking list --- diff --git a/src/lib/io/all.mk b/src/lib/io/all.mk index bac0ac30e9c..56ea3518142 100644 --- a/src/lib/io/all.mk +++ b/src/lib/io/all.mk @@ -12,7 +12,6 @@ SOURCES := \ queue.c \ ring_buffer.c \ schedule.c \ - time_tracking.c \ worker.c TGT_PREREQS := $(LIBFREERADIUS_SERVER) libfreeradius-util.la diff --git a/src/lib/io/time_tracking.c b/src/lib/io/time_tracking.c deleted file mode 100644 index 717e878124a..00000000000 --- a/src/lib/io/time_tracking.c +++ /dev/null @@ -1,148 +0,0 @@ -/* - * This program is free software; you can redistribute it and/or modify - * it under the terms of the GNU General Public License as published by - * the Free Software Foundation; either version 2 of the License, or - * (at your option) any later version. - * - * This program is distributed in the hope that it will be useful, - * but WITHOUT ANY WARRANTY; without even the implied warranty of - * MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the - * GNU General Public License for more details. - * - * You should have received a copy of the GNU General Public License - * along with this program; if not, write to the Free Software - * Foundation, Inc., 51 Franklin St, Fifth Floor, Boston, MA 02110-1301, USA - */ - -/** - * $Id$ - * - * @brief Time tracking for requests - * @file lib/util/time_tracking.c - * - * @copyright 2016 Alan DeKok (aland@freeradius.org) - */ -RCSID("$Id$") - -#include - -/** Start time tracking for a request. - * - * @param[in] tt the time tracking structure. - * @param[in] when the event happened - * @param[out] worker time tracking for the worker thread - */ -void fr_time_tracking_start(fr_time_tracking_t *tt, fr_time_t when, fr_time_tracking_t *worker) -{ - memset(tt, 0, sizeof(*tt)); - - tt->when = when; - tt->start = when; - tt->resumed = when; - - fr_dlist_init(&worker->list, fr_time_tracking_t, list.entry); - fr_dlist_init(&(tt->list), fr_time_tracking_t, list.entry); -} - - -#define IALPHA (8) -#define RTT(_old, _new) ((_new + ((IALPHA - 1) * _old)) / IALPHA) - -/** End time tracking for this request. - * - * After this call, all request processing should be finished. - * - * @param[in] tt the time tracking structure. - * @param[in] when the event happened - * @param[out] worker time tracking for the worker thread - */ -void fr_time_tracking_end(fr_time_tracking_t *tt, fr_time_t when, fr_time_tracking_t *worker) -{ - tt->when = when; - tt->end = when; - tt->running += (tt->end - tt->resumed); - - /* - * This request cannot be in any list. - */ - rad_assert(!fr_dlist_entry_in_list(&tt->list.entry)); - - /* - * Update the time that the worker spent processing the request. - */ - worker->running += tt->running; - worker->waiting += tt->waiting; - - if (!worker->predicted) { - worker->predicted = tt->running; - } else { - worker->predicted = RTT(worker->predicted, tt->running); - } -} - - -/** Track that a request yielded. - * - * @param[in] tt the time tracking structure. - * @param[in] when the event happened - * @param[out] worker time tracking for the worker thread - */ -void fr_time_tracking_yield(fr_time_tracking_t *tt, fr_time_t when, fr_time_tracking_t *worker) -{ - tt->when = when; - tt->yielded = when; - - rad_assert(tt->resumed <= tt->yielded); - tt->running += (tt->yielded - tt->resumed); - - /* - * Insert this request into the TAIL of the worker's list - * of waiting requests. - */ - fr_dlist_insert_head(&worker->list, tt); -} - - -/** Track that a request resumed. - * - * @param[in] tt the time tracking structure. - * @param[in] when the event happened - * @param[out] worker time tracking for the worker thread - */ -void fr_time_tracking_resume(fr_time_tracking_t *tt, fr_time_t when, fr_time_tracking_t *worker) -{ - tt->when = when; - tt->resumed = when; - - rad_assert(tt->resumed >= tt->yielded); - - tt->waiting += (tt->resumed - tt->yielded); - - /* - * Remove this request into the workers list of waiting - * requests. - */ - fr_dlist_remove(&worker->list, tt); -} - - -/** Print debug information about the time tracking structure - * - * @param[in] tt the time tracking structure - * @param[in] fp the file where the debug output is printed. - */ -void fr_time_tracking_debug(fr_time_tracking_t *tt, FILE *fp) -{ -#define DPRINT(_x) fprintf(fp, "\t" #_x " = %"PRIu64"\n", tt->_x); - - DPRINT(start); - DPRINT(end); - DPRINT(when); - - DPRINT(yielded); - DPRINT(resumed); - - DPRINT(predicted); - DPRINT(running); - DPRINT(waiting); -} diff --git a/src/lib/io/time_tracking.h b/src/lib/io/time_tracking.h index 251d31ff798..b7c1ae4cc4f 100644 --- a/src/lib/io/time_tracking.h +++ b/src/lib/io/time_tracking.h @@ -21,6 +21,7 @@ * @file lib/io/time_tracking.h * @brief Request time tracking * + * @copyright 2019 Arran Cudbard-Bell (a.cudbardb@freeradius.org) * @copyright 2016 Alan DeKok (aland@freeradius.org) */ RCSIDH(time_tracking_h, "$Id$") @@ -29,8 +30,17 @@ RCSIDH(time_tracking_h, "$Id$") extern "C" { #endif +#include #include +typedef enum { + FR_TIME_TRACKING_STOPPED = 0, //!< Time tracking is not running. + FR_TIME_TRACKING_RUNNING, //!< We're currently tracking time in the + ///< running state. + FR_TIME_TRACKING_YIELDED //!< We're currently tracking time in the + ///< yielded state. +} fr_time_tracking_state_t; + /** A structure to track the time spent processing a request. * * The same structure is used by threads to track when they are @@ -42,24 +52,245 @@ extern "C" { * While fr_time() is fast, it is also called very often. We should * therefore be careful to call it only when necessary. */ -typedef struct { - fr_time_t when; //!< last time we changed a field - fr_time_t start; //!< time this request started being processed - fr_time_t end; //!< when we stopped processing this request - fr_time_t predicted; //!< predicted processing time for this request - fr_time_t yielded; //!< time this request yielded - fr_time_t resumed; //!< time this request last resumed; - fr_time_t running; //!< total time spent running - fr_time_t waiting; //!< total time spent waiting - - fr_dlist_head_t list; //!< for linking a request to various lists -} fr_time_tracking_t; - -void fr_time_tracking_start(fr_time_tracking_t *tt, fr_time_t when, fr_time_tracking_t *worker) CC_HINT(nonnull); -void fr_time_tracking_end(fr_time_tracking_t *tt, fr_time_t when, fr_time_tracking_t *worker) CC_HINT(nonnull); -void fr_time_tracking_yield(fr_time_tracking_t *tt, fr_time_t when, fr_time_tracking_t *worker) CC_HINT(nonnull); -void fr_time_tracking_resume(fr_time_tracking_t *tt, fr_time_t when, fr_time_tracking_t *worker) CC_HINT(nonnull); -void fr_time_tracking_debug(fr_time_tracking_t *tt, FILE *fp) CC_HINT(nonnull); +typedef struct fr_time_tracking_s fr_time_tracking_t; +struct fr_time_tracking_s { + fr_time_tracking_state_t state; //!< What state we're currently in. + ///< only used for the leaf node. + fr_time_t last_changed; //!< last time we changed a field + + fr_time_t started; //!< Last time this tracked entity or a child + ///< entered the running state, or entered + ///< a time tracked parent. + + fr_time_t last_yielded; //!< Last time this tracked entity or a child + ///< yielded. + + fr_time_t last_resumed; //!< Last time this tracked entity or a child + ///< resumed; + + fr_time_t ended; //!< Last time this tracked entity or a child + ///< left the running state, or popped a time + ///< tracked parent. + + fr_time_delta_t running_total; //!< total time spent running + fr_time_delta_t waiting_total; //!< total time spent waiting + + fr_time_tracking_t *parent; //!< To update with our time tracking data when + ///< tracking is complete. +}; + +/** We use a monotonic time source + * + */ +#define ASSERT_ON_TIME_TRAVEL(_tt, _now) \ +do { \ + rad_assert((_tt)->last_changed <= (_now)); \ + rad_assert((_tt)->started <= (_now)); \ + rad_assert((_tt)->ended <= (_now)); \ + rad_assert((_tt)->last_yielded <= (_now)); \ + rad_assert((_tt)->last_resumed <= (_now)); \ +} while(0); + +/** Set the last time a tracked entity started in its list of parents + * + */ +#define UPDATE_PARENT_START_TIME(_tt, _now) \ +do { \ + fr_time_tracking_t *_parent; \ + for (_parent = (_tt)->parent; _parent; _parent = _parent->parent) { \ + _parent->started = _parent->last_changed = _now; \ + } \ +} while (0) + +/** Update total run time up the list of parents + * + */ +#define UPDATE_PARENT_RUN_TIME(_tt, _run_time, _event, _now) \ +do { \ + fr_time_tracking_t *_parent; \ + for (_parent = (_tt)->parent; _parent; _parent = _parent->parent) { \ + _parent->_event = _parent->last_changed = _now; \ + _parent->running_total += _run_time; \ + } \ +} while (0) + +/** Update total wait time up the list of parents + * + */ +#define UPDATE_PARENT_WAIT_TIME(_tt, _wait_time, _event, _now) \ +do { \ + fr_time_tracking_t *_parent; \ + for (_parent = (_tt)->parent; _parent; _parent = _parent->parent){ \ + _parent->_event = _parent->last_changed = _now; \ + _parent->running_total += _wait_time; \ + } \ +} while (0) + +/** Initialise a time tracking structure + * + */ +static inline CC_HINT(nonnull) void fr_time_tracking_init(fr_time_tracking_t *tt) +{ + memset(tt, 0, sizeof(*tt)); +} + +/** Start time tracking for a tracked entity + * + * Should be called when the tracked entity starts running. + * + * @param[in] parent to update when time tracking ends. + * @param[in] tt the time tracked entity. + * @param[in] now the current time. + */ +static inline CC_HINT(nonnull) void fr_time_tracking_start(fr_time_tracking_t *parent, + fr_time_tracking_t *tt, fr_time_t now) +{ + rad_assert(tt->state == FR_TIME_TRACKING_STOPPED); + rad_assert(!tt->parent); + + ASSERT_ON_TIME_TRAVEL(tt, now); + + tt->state = FR_TIME_TRACKING_RUNNING; + tt->started = tt->last_changed = now; + + tt->parent = parent; + + UPDATE_PARENT_START_TIME(tt, now); +} + +/** Tracked entity entered a deeper time tracked code area + * + * @param[in] parent we entered. Must be a direct descendent of the + * current tt->parent. + * @param[in] tt the time tracked entity. + * @param[in] now the current time. + */ +static inline CC_HINT(nonnull) void fr_time_tracking_push(fr_time_tracking_t *parent, + fr_time_tracking_t *tt, fr_time_t now) +{ + fr_time_delta_t run_time; + + rad_assert(parent->parent = tt->parent); + + rad_assert(tt->state == FR_TIME_TRACKING_RUNNING); + tt->last_changed = parent->started = now; + + run_time = now - tt->last_changed; + UPDATE_PARENT_RUN_TIME(tt, run_time, last_changed, now); + + tt->parent = parent; +} + +/** Tracked entity left a tracked nested code area + * + * Updates parent to point to the current time tracking parent. + * + * @param[in] tt the time tracked entity. + * @param[in] now the current time. + */ +static inline CC_HINT(nonnull) void fr_time_tracking_pop(fr_time_tracking_t *tt, fr_time_t now) +{ + fr_time_delta_t run_time; + + rad_assert(tt->state == FR_TIME_TRACKING_RUNNING); + tt->last_changed = tt->parent->ended = now; + + run_time = now - tt->last_changed; + tt->running_total += run_time; + UPDATE_PARENT_RUN_TIME(tt, run_time, last_changed, now); + + tt->parent = tt->parent->parent; +} + +/** Transition to the yielded state, recording the time we just spent running + * + * @param[in] tt the time tracked entity. + * @param[in] now the current time. + */ +static inline CC_HINT(nonnull) void fr_time_tracking_yield(fr_time_tracking_t *tt, fr_time_t now) +{ + fr_time_delta_t run_time; + + ASSERT_ON_TIME_TRAVEL(tt, now); + + rad_assert(tt->state == FR_TIME_TRACKING_RUNNING); + tt->state = FR_TIME_TRACKING_YIELDED; + tt->last_yielded = tt->last_changed = now; + + run_time = now - tt->last_changed; + tt->running_total += run_time; + UPDATE_PARENT_RUN_TIME(tt, run_time, last_yielded, now); +} + +/** Track that a request resumed. + * + * @param[in] tt the time tracked entity. + * @param[in] now the current time. + */ +static inline CC_HINT(nonnull) void fr_time_tracking_resume(fr_time_tracking_t *tt, fr_time_t now) +{ + fr_time_delta_t wait_time; + + ASSERT_ON_TIME_TRAVEL(tt, now); + + rad_assert(tt->state == FR_TIME_TRACKING_YIELDED); + tt->state = FR_TIME_TRACKING_RUNNING; + tt->last_resumed = tt->last_changed = now; + + wait_time = now - tt->last_changed; + tt->waiting_total += wait_time; + UPDATE_PARENT_WAIT_TIME(tt, wait_time, last_resumed, now); +} + +#define IALPHA (8) +#define RTT(_old, _new) ((_new + ((IALPHA - 1) * _old)) / IALPHA) + +/** End time tracking for this entity + * + * @param[in,out] predicted Update our prediction of how long requests should run for. + * @param[in] tt the time tracking structure. + * @param[in] now the current time. + */ +static inline void fr_time_tracking_end(fr_time_delta_t *predicted, + fr_time_tracking_t *tt, fr_time_t now) +{ + fr_time_tracking_t *parent; + fr_time_delta_t run_time; + + rad_assert(tt->state == FR_TIME_TRACKING_RUNNING); + ASSERT_ON_TIME_TRAVEL(tt, now); + + tt->state = FR_TIME_TRACKING_STOPPED; + tt->ended = tt->last_changed = now; + + run_time = now - tt->last_changed; + tt->running_total += run_time; + UPDATE_PARENT_RUN_TIME(tt, run_time, ended, now); + + if (predicted) *predicted = !(*predicted) ? tt->running_total : RTT((*predicted), tt->running_total); + + parent = NULL; +} + +/** Print debug information about the time tracking structure + * + * @param[in] tt the time tracking structure + * @param[in] fp the file where the debug output is printed. + */ +static inline CC_HINT(nonnull) void fr_time_tracking_debug(fr_time_tracking_t *tt, FILE *fp) +{ +#define DPRINT(_x) fprintf(fp, "\t" #_x " = %"PRIu64"\n", tt->_x); + + DPRINT(started); + DPRINT(ended); + DPRINT(last_changed); + + DPRINT(last_yielded); + DPRINT(last_resumed); + + DPRINT(running_total); + DPRINT(waiting_total); +} #ifdef __cplusplus } diff --git a/src/lib/io/worker.c b/src/lib/io/worker.c index a2cbffdddca..40529174eaf 100644 --- a/src/lib/io/worker.c +++ b/src/lib/io/worker.c @@ -90,7 +90,7 @@ static void fr_worker_verify(fr_worker_t *worker); /** * A worker which takes packets from a master, and processes them. */ -struct fr_worker_t { +struct fr_worker_s { char const *name; //!< name of this worker pthread_t id; //!< my thread ID @@ -132,6 +132,7 @@ struct fr_worker_t { uint64_t num_timeouts; //!< number of messages which timed out uint64_t num_active; //!< number of active requests + fr_time_delta_t predicted; //!< How long we predict a request will take to execute. fr_time_tracking_t tracking; //!< how much time the worker has spent doing things. bool was_sleeping; //!< used to suppress multiple sleep signals in a row @@ -367,7 +368,7 @@ static void fr_worker_nak(fr_worker_t *worker, fr_channel_data_t *cd, fr_time_t * Fill in the NAK. */ reply->m.when = now; - reply->reply.cpu_time = worker->tracking.running; + reply->reply.cpu_time = worker->tracking.running_total; reply->reply.processing_time = 10; /* @todo - set to something better? */ reply->reply.request_time = cd->m.when; @@ -421,7 +422,7 @@ static void fr_worker_send_reply(fr_worker_t *worker, REQUEST *request, size_t s * Just toss the request. */ if (request->async->fake) { - fr_time_tracking_end(&request->async->tracking, now, &worker->tracking); + fr_time_tracking_end(&worker->predicted, &request->async->tracking, now); goto finished; } @@ -469,7 +470,7 @@ static void fr_worker_send_reply(fr_worker_t *worker, REQUEST *request, size_t s /* * The request is done. Track that. */ - fr_time_tracking_end(&request->async->tracking, now, &worker->tracking); + fr_time_tracking_end(&worker->predicted, &request->async->tracking, now); rad_assert(worker->num_active > 0); worker->num_active--; @@ -485,9 +486,9 @@ static void fr_worker_send_reply(fr_worker_t *worker, REQUEST *request, size_t s * * sequence / ack will be filled in by fr_channel_send_reply() */ - reply->m.when = request->async->tracking.when; - reply->reply.cpu_time = worker->tracking.running; - reply->reply.processing_time = request->async->tracking.running; + reply->m.when = request->async->tracking.last_changed; + reply->reply.cpu_time = worker->tracking.running_total; + reply->reply.processing_time = request->async->tracking.running_total; reply->reply.request_time = request->async->recv_time; reply->listen = request->async->listen; @@ -525,7 +526,6 @@ finished: request->async->original_recv_time = NULL; request->async->el = NULL; request->async->process = NULL; - fr_dlist_remove(&worker->tracking.list, &request->async->tracking); request->async->channel = NULL; request->async->packet_ctx = NULL; request->async->listen = NULL; @@ -541,7 +541,7 @@ finished: */ static void worker_stop_request(fr_worker_t *worker, REQUEST *request, fr_time_t now) { - fr_time_tracking_resume(&request->async->tracking, now, &worker->tracking); + fr_time_tracking_resume(&request->async->tracking, now); unlang_interpret_signal(request, FR_SIGNAL_CANCEL); /* @@ -757,7 +757,7 @@ static REQUEST *fr_worker_get_request(fr_worker_t *worker, fr_time_t now) DEBUG3("%s found runnable request", worker->name); REQUEST_VERIFY(request); rad_assert(request->runnable_id < 0); - fr_time_tracking_resume(&request->async->tracking, now, &worker->tracking); + fr_time_tracking_resume(&request->async->tracking, now); return request; } @@ -947,7 +947,7 @@ nak: * Bootstrap the async state machine with the initial * state of the request. */ - fr_time_tracking_start(&request->async->tracking, now, &worker->tracking); + fr_time_tracking_start(&worker->tracking, &request->async->tracking, now); worker->num_active++; rad_assert(request->runnable_id < 0); @@ -1012,7 +1012,7 @@ static void fr_worker_run_request(fr_worker_t *worker, REQUEST *request) break; case RLM_MODULE_YIELD: - fr_time_tracking_yield(&request->async->tracking, fr_time(), &worker->tracking); + fr_time_tracking_yield(&request->async->tracking, fr_time()); return; case RLM_MODULE_OK: @@ -1295,7 +1295,6 @@ nomem: * the worker thread is running. */ memset(&worker->tracking, 0, sizeof(worker->tracking)); - fr_dlist_init(&worker->tracking.list, fr_time_tracking_t, list.entry); worker->aq_control = fr_atomic_queue_create(worker, 1024); if (!worker->aq_control) { @@ -1478,9 +1477,9 @@ void fr_worker_debug(fr_worker_t *worker, FILE *fp) fprintf(fp, "\tstats.in = %" PRIu64 "\n", worker->stats.in); fprintf(fp, "\tcalculated (predicted) total CPU time = %" PRIu64 "\n", - worker->tracking.predicted * worker->stats.in); + worker->predicted * worker->stats.in); fprintf(fp, "\tcalculated (counted) per request time = %" PRIu64 "\n", - worker->tracking.running / worker->stats.in); + worker->tracking.running_total / worker->stats.in); fr_time_tracking_debug(&worker->tracking, fp); @@ -1612,13 +1611,13 @@ static int cmd_stats_worker(FILE *fp, UNUSED FILE *fp_err, void *ctx, fr_cmd_inf } if ((info->argc == 0) || (strcmp(info->argv[0], "cpu") == 0)) { - when = worker->tracking.predicted; + when = worker->predicted; fprintf(fp, "cpu.average_request_time\t%u.%03u\n", (unsigned int) (when / NSEC), (unsigned int) (when % NSEC) / 1000000); - when = worker->tracking.running; + when = worker->tracking.running_total; fprintf(fp, "cpu.used\t\t\t%u.%03u\n", (unsigned int) (when / NSEC), (unsigned int) (when % NSEC) / 1000000); - when = worker->tracking.waiting; + when = worker->tracking.waiting_total; fprintf(fp, "cpu.waiting\t\t\t%u.%03u\n", (unsigned int) (when / NSEC), (unsigned int) (when % NSEC) / 1000000); when = fr_time() - worker->last_event; diff --git a/src/lib/io/worker.h b/src/lib/io/worker.h index 04aec7a8e5c..97aec83d7ad 100644 --- a/src/lib/io/worker.h +++ b/src/lib/io/worker.h @@ -35,7 +35,7 @@ extern "C" { * * Once spawned, workers exist until they choose to exit. */ -typedef struct fr_worker_t fr_worker_t; +typedef struct fr_worker_s fr_worker_t; #ifdef __cplusplus } diff --git a/src/lib/unlang/io.c b/src/lib/unlang/io.c index 9d4915ba980..4d9f0b18f63 100644 --- a/src/lib/unlang/io.c +++ b/src/lib/unlang/io.c @@ -118,12 +118,5 @@ REQUEST *unlang_io_subrequest_alloc(REQUEST *parent, fr_dict_t const *namespace, */ child->async->process = unlang_io_process_interpret; - /* - * Note that we don't do time tracking on the child. - * Instead, all of it is done in the context of the - * parent. - */ - fr_dlist_init(&child->async->tracking.list, fr_time_tracking_t, list.entry); - return child; }