MINOR: activity: report the average loop time in "show activity"

Since we know the time it takes to process everything between two poll()
calls, we can use this as the max latency measurement any task will
experience and average it.

This code does this, and reports in "show activity" the average of this
loop time over the last 1024 poll() loops, for each thread. It will vary
quickly at high loads and slowly under low to moderate loads, depending
on the rate at which poll() is called. The latency a task experiences
is expected to be half of this on average.
This commit is contained in:
Willy Tarreau 2018-11-22 08:42:42 +01:00
parent 609aad9e73
commit baba82fe70
3 changed files with 10 additions and 0 deletions

View File

@ -26,6 +26,7 @@
#include <common/hathreads.h>
#include <common/time.h>
#include <types/activity.h>
#include <proto/freq_ctr.h>
extern struct activity activity[MAX_THREADS];
@ -34,12 +35,15 @@ void report_stolen_time(uint64_t stolen);
/* Collect date and time information before calling poll(). This will be used
* to count the run time of the past loop and the sleep time of the next poll.
* It also makes use of the just updated before_poll timer to count the loop's
* run time and feed the average loop time metric (in microseconds).
*/
static inline void activity_count_runtime()
{
uint64_t new_mono_time;
uint64_t new_cpu_time;
int64_t stolen;
uint32_t run_time;
new_cpu_time = now_cpu_time();
new_mono_time = now_mono_time();
@ -56,6 +60,9 @@ static inline void activity_count_runtime()
report_stolen_time(stolen);
}
}
run_time = (before_poll.tv_sec - after_poll.tv_sec) * 1000000U + (before_poll.tv_usec - after_poll.tv_usec);
swrate_add(&activity[tid].avg_loop_us, TIME_STATS_SAMPLES, run_time);
}

View File

@ -47,8 +47,10 @@ struct activity {
unsigned int empty_rq; // calls to process_runnable_tasks() with nothing for the thread
unsigned int long_rq; // process_runnable_tasks() left with tasks in the run queue
unsigned int cpust_total; // sum of half-ms stolen per thread
/* one cache line */
struct freq_ctr cpust_1s; // avg amount of half-ms stolen over last second
struct freq_ctr_period cpust_15s; // avg amount of half-ms stolen over last 15s
unsigned int avg_loop_us; // average run time per loop over last 1024 runs
char __pad[0]; // unused except to check remaining room
char __end[0] __attribute__((aligned(64))); // align size to 64.
};

View File

@ -1004,6 +1004,7 @@ static int cli_io_handler_show_activity(struct appctx *appctx)
chunk_appendf(&trash, "\ncpust_tot:"); for (thr = 0; thr < global.nbthread; thr++) chunk_appendf(&trash, " %u", activity[thr].cpust_total/2);
chunk_appendf(&trash, "\ncpust_1s:"); for (thr = 0; thr < global.nbthread; thr++) chunk_appendf(&trash, " %u", read_freq_ctr(&activity[thr].cpust_1s)/2);
chunk_appendf(&trash, "\ncpust_15s:"); for (thr = 0; thr < global.nbthread; thr++) chunk_appendf(&trash, " %u", read_freq_ctr_period(&activity[thr].cpust_15s, 15000)/2);
chunk_appendf(&trash, "\navg_loop_us:"); for (thr = 0; thr < global.nbthread; thr++) chunk_appendf(&trash, " %u", swrate_avg(activity[thr].avg_loop_us, TIME_STATS_SAMPLES));
chunk_appendf(&trash, "\n");