lib/tst_timer_test.c

/*
 * Copyright (c) 2017 Cyril Hrubis <chrubis@suse.cz>
 *
 * 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, see <http://www.gnu.org/licenses/>.
 */

#include <sys/prctl.h>
#include <stdlib.h>
#include <stdio.h>
#include <limits.h>

#define TST_NO_DEFAULT_MAIN
#include "tst_test.h"
#include "tst_clocks.h"
#include "tst_timer_test.h"

#define MAX_SAMPLES 500

static const char *scall;
static void (*setup)(void);
static void (*cleanup)(void);
static int (*sample)(int clk_id, long long usec);
static struct tst_test *test;

static long long *samples;
static unsigned int cur_sample;
static unsigned int monotonic_resolution;
static unsigned int timerslack;

static char *print_frequency_plot;
static char *file_name;
static char *str_sleep_time;
static char *str_sample_cnt;
static int sleep_time = -1;
static int sample_cnt;

static void print_line(char c, int len)
{
	while (len-- > 0)
		fputc(c, stderr);
}

static unsigned int ceilu(float f)
{
	if (f - (int)f > 0)
		return (unsigned int)f + 1;

	return (unsigned int)f;
}

static unsigned int flooru(float f)
{
	return (unsigned int)f;
}

static float bucket_len(unsigned int bucket, unsigned int max_bucket,
		        unsigned int cols)
{
	return 1.00 * bucket * cols / max_bucket;
}

static const char *table_heading = " Time: us ";

/*
 * Line Header: '10023 | '
 */
static unsigned int header_len(long long max_sample)
{
	unsigned int l = 1;

	while (max_sample/=10)
		l++;

	return MAX(strlen(table_heading) + 2, l + 3);
}

static void frequency_plot(void)
{
	unsigned int cols = 80;
	unsigned int rows = 20;
	unsigned int i, buckets[rows];
	long long max_sample = samples[0];
	long long min_sample = samples[cur_sample-1];
	unsigned int line_header_len = header_len(max_sample);
	unsigned int plot_line_len = cols - line_header_len;
	unsigned int bucket_size;

	memset(buckets, 0, sizeof(buckets));

	/*
	 * We work with discrete data buckets smaller than 1 does not make
	 * sense as well as it's a good idea to keep buckets integer sized
	 * to avoid scaling artifacts.
	 */
	bucket_size = MAX(1u, ceilu(1.00 * (max_sample - min_sample)/(rows-1)));

	for (i = 0; i < cur_sample; i++) {
		unsigned int bucket;
		bucket = flooru(1.00 * (samples[i] - min_sample)/bucket_size);
		buckets[bucket]++;
	}

	unsigned int max_bucket = buckets[0];
	for (i = 1; i < rows; i++)
		max_bucket = MAX(max_bucket, buckets[i]);

	fprintf(stderr, "\n%*s| Frequency\n", line_header_len - 2, table_heading);

	print_line('-', cols);
	fputc('\n', stderr);

	unsigned int l, r;

	for (l = 0; l < rows; l++) {
		if (buckets[l])
			break;
	}

	for (r = rows-1; r > l; r--) {
		if (buckets[r])
			break;
	}

	for (i = l; i <= r; i++) {
		float len = bucket_len(buckets[i], max_bucket, plot_line_len);

		fprintf(stderr, "%*lli | ",
			line_header_len - 3, min_sample + bucket_size*i);
		print_line('*', len);

		if ((len - (int)len) >= 0.5)
			fputc('+', stderr);
		else if ((len - (int)len) >= 0.25)
			fputc('-', stderr);
		else if (len < 0.25 && buckets[i])
			fputc('.', stderr);

		fputc('\n', stderr);
	}

	print_line('-', cols);
	fputc('\n', stderr);

	float scale = 1.00 * plot_line_len / max_bucket;

	fprintf(stderr,
		"%*uus | 1 sample = %.5f '*', %.5f '+', %.5f '-', non-zero '.'\n",
		line_header_len - 5, bucket_size, scale, scale * 2, scale * 4);

	fputc('\n', stderr);
}

void tst_timer_sample(void)
{
	samples[cur_sample++] = tst_timer_elapsed_us();
}

static int cmp(const void *a, const void *b)
{
	const long long *aa = a, *bb = b;

	return *aa < *bb;
}

/*
 * The threshold per one syscall is computed as a sum of:
 *
 *  400 us                 - accomodates for context switches, process
 *                           migrations between CPUs on SMP, etc.
 *  2*monotonic_resolution - accomodates for granurality of the CLOCK_MONOTONIC
 *  slack_per_scall        - max of 0.1% of the sleep capped on 100ms or
 *                           current->timer_slack_ns, which is slack allowed
 *                           in kernel
 *
 *  The formula	for slack_per_scall applies to select() and *poll*() syscalls,
 *  the futex and *nanosleep() use only the timer_slack_ns, so we are a bit
 *  less strict here that we could be for these two for longer sleep times...
 *
 * We also allow for outliners, i.e. add some number to the threshold in case
 * that the number of iteration is small. For large enoung number of iterations
 * outliners are discarded and averaged out.
 */
static long long compute_threshold(long long requested_us,
				   unsigned int nsamples)
{
	unsigned int slack_per_scall = MIN(100000, requested_us / 1000);

	slack_per_scall = MAX(slack_per_scall, timerslack);

	return (400 + 2 * monotonic_resolution + slack_per_scall) * nsamples
		+ 3000/nsamples;
}

/*
 * Returns number of samples to discard.
 *
 * We set it to either at least 1 if number of samples > 1 or 5%.
 */
static unsigned int compute_discard(unsigned int nsamples)
{
	if (nsamples == 1)
		return 0;

	return MAX(1u, nsamples / 20);
}

static void write_to_file(void)
{
	unsigned int i;
	FILE *f;

	if (!file_name)
		return;

	f = fopen(file_name, "w");

	if (!f) {
		tst_res(TWARN | TERRNO,
			"Failed to open '%s'", file_name);
		return;
	}

	for (i = 0; i < cur_sample; i++)
		fprintf(f, "%lli\n", samples[i]);

	if (fclose(f)) {
		tst_res(TWARN | TERRNO,
			"Failed to close file '%s'", file_name);
	}
}


/*
 * Timer testing function.
 *
 * What we do here is:
 *
 * * Take nsamples measurements of the timer function, the function
 *   to be sampled is defined in the the actual test.
 *
 * * We sort the array of samples, then:
 *
 *   - look for outliners which are samples where the sleep time has exceeded
 *     requested sleep time by an order of magnitude and, at the same time, are
 *     greater than clock resolution multiplied by three.
 *
 *   - check for samples where the call has woken up too early which is a plain
 *     old bug
 *
 *   - then we compute truncated mean and compare that with the requested sleep
 *     time increased by a threshold
 */
void do_timer_test(long long usec, unsigned int nsamples)
{
	long long trunc_mean, median;
	unsigned int discard = compute_discard(nsamples);
	unsigned int keep_samples = nsamples - discard;
	long long threshold = compute_threshold(usec, keep_samples);
	int i;
	int failed = 0;

	tst_res(TINFO,
		"%s sleeping for %llius %u iterations, threshold %.2fus",
		scall, usec, nsamples, 1.00 * threshold / (keep_samples));

	cur_sample = 0;
	for (i = 0; i < (int)nsamples; i++) {
		if (sample(CLOCK_MONOTONIC, usec)) {
			tst_res(TINFO, "sampling function failed, exitting");
			return;
		}
	}

	qsort(samples, nsamples, sizeof(samples[0]), cmp);

	write_to_file();

	for (i = 0; samples[i] > 10 * usec && i < (int)nsamples; i++) {
		if (samples[i] <= 3 * monotonic_resolution)
			break;
	}

	if (i > 0) {
		tst_res(TINFO, "Found %i outliners in [%lli,%lli] range",
			i, samples[0], samples[i-1]);
	}

	for (i = nsamples - 1; samples[i] < usec && i > -1; i--);

	if (i < (int)nsamples - 1) {
		tst_res(TFAIL, "%s woken up early %u times range: [%lli,%lli]",
			scall, nsamples - 1 - i,
			samples[i+1], samples[nsamples-1]);
		failed = 1;
	}

	median = samples[nsamples/2];

	trunc_mean = 0;

	for (i = discard; i < (int)nsamples; i++)
		trunc_mean += samples[i];

	tst_res(TINFO,
		"min %llius, max %llius, median %llius, trunc mean %.2fus (discarded %u)",
		samples[nsamples-1], samples[0], median,
		1.00 * trunc_mean / keep_samples, discard);

	if (trunc_mean > (nsamples - discard) * usec + threshold) {
		tst_res(TFAIL, "%s slept for too long", scall);

		if (!print_frequency_plot)
			frequency_plot();

		failed = 1;
	}

	if (print_frequency_plot)
		frequency_plot();

	if (!failed)
		tst_res(TPASS, "Measured times are within thresholds");
}

static void parse_timer_opts(void);

static int set_latency(void)
{
        int fd, latency = 0;

        fd = open("/dev/cpu_dma_latency", O_WRONLY);
        if (fd < 0)
                return fd;

        return write(fd, &latency, sizeof(latency));
}

static void timer_setup(void)
{
	struct timespec t;
	int ret;

	tst_clock_getres(CLOCK_MONOTONIC, &t);

	tst_res(TINFO, "CLOCK_MONOTONIC resolution %lins", (long)t.tv_nsec);

	monotonic_resolution = t.tv_nsec / 1000;
	timerslack = 50;

#ifdef PR_GET_TIMERSLACK
	ret = prctl(PR_GET_TIMERSLACK);
	if (ret < 0) {
		tst_res(TINFO, "prctl(PR_GET_TIMERSLACK) = -1, using %uus",
			timerslack);
	} else {
		timerslack = ret / 1000;
		tst_res(TINFO, "prctl(PR_GET_TIMERSLACK) = %ius", timerslack);
	}
#else
	tst_res(TINFO, "PR_GET_TIMERSLACK not defined, using %uus",
		timerslack);
#endif /* PR_GET_TIMERSLACK */

	parse_timer_opts();

	samples = SAFE_MALLOC(sizeof(long long) * MAX(MAX_SAMPLES, sample_cnt));

	if (set_latency() < 0)
		tst_res(TINFO, "Failed to set zero latency constraint: %m");

	if (setup)
		setup();
}

static void timer_cleanup(void)
{
	free(samples);

	if (cleanup)
		cleanup();
}

static struct tst_timer_tcase {
	long long usec;
	unsigned int samples;
} tcases[] = {
	{1000,  500},
	{2000,  500},
	{5000,  300},
	{10000, 100},
	{25000,  50},
	{100000, 10},
	{1000000, 2},
};

static void timer_test_fn(unsigned int n)
{
	do_timer_test(tcases[n].usec, tcases[n].samples);
}

static void single_timer_test(void)
{
	do_timer_test(sleep_time, sample_cnt);
}

static struct tst_option options[] = {
	{"p",  &print_frequency_plot, "-p       Print frequency plot"},
	{"s:", &str_sleep_time, "-s us    Sleep time"},
	{"n:", &str_sample_cnt, "-n uint  Number of samples to take"},
	{"f:", &file_name, "-f fname Write measured samples into a file"},
	{NULL, NULL, NULL}
};

static void parse_timer_opts(void)
{
	if (str_sleep_time) {
		if (tst_parse_int(str_sleep_time, &sleep_time, 0, INT_MAX)) {
			tst_brk(TBROK,
				"Invalid sleep time '%s'", str_sleep_time);
		}
	}

	if (str_sample_cnt) {
		if (tst_parse_int(str_sample_cnt, &sample_cnt, 1, INT_MAX)) {
			tst_brk(TBROK,
				"Invalid sample count '%s'", str_sample_cnt);
		}
	}

	if (str_sleep_time || str_sample_cnt) {
		if (sleep_time < 0)
			sleep_time = 10000;

		if (!sample_cnt)
			sample_cnt = 500;

		long long timeout = sleep_time * sample_cnt / 1000000;

		tst_set_timeout(timeout + timeout/10);

		test->test_all = single_timer_test;
		test->test = NULL;
		test->tcnt = 0;
	}
}

struct tst_test *tst_timer_test_setup(struct tst_test *timer_test)
{
	setup = timer_test->setup;
	cleanup = timer_test->cleanup;
	scall = timer_test->scall;
	sample = timer_test->sample;

	timer_test->scall = NULL;
	timer_test->setup = timer_setup;
	timer_test->cleanup = timer_cleanup;
	timer_test->test = timer_test_fn;
	timer_test->tcnt = ARRAY_SIZE(tcases);
	timer_test->sample = NULL;
	timer_test->options = options;

	test = timer_test;

	return timer_test;
}