+++ /dev/null
-/*
- * 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 <freeradius-devel/io/time_tracking.h>
-
-/** 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);
-}
* @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$")
extern "C" {
#endif
+#include <freeradius-devel/server/rad_assert.h>
#include <freeradius-devel/util/time.h>
+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
* 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
}
/**
* 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
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
* 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;
* 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;
}
/*
* 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--;
*
* 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;
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;
*/
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);
/*
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;
}
* 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);
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:
* 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) {
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);
}
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;
projects / thirdparty / freeradius-server.git / commitdiff
