[PATCH v2] Import a new test, jitterz

[PATCH v2] Import a new test, jitterz

[trix]

From: Tom Rix <trix@redhat.com>

jitterz is a program for measuring system jitter.

It is a rewrite of sysjitter
https://github.com/alexeiz/sysjitter

The upstream location of jitterz is
https://github.com/trixirt/jitterz

Signed-off-by: Tom Rix <trix@redhat.com>
---
 Makefile              |  10 +-
 src/jitterz/jitterz.8 |  39 ++++
 src/jitterz/jitterz.c | 400 ++++++++++++++++++++++++++++++++++++++++++
 3 files changed, 447 insertions(+), 2 deletions(-)
 create mode 100644 src/jitterz/jitterz.8
 create mode 100644 src/jitterz/jitterz.c

diff --git a/Makefile b/Makefile
index 05fc5ed..3a88a5f 100644
--- a/Makefile
+++ b/Makefile
@@ -17,7 +17,8 @@ sources = cyclictest.c \
 	  cyclicdeadline.c \
 	  deadline_test.c \
 	  queuelat.c \
-	  ssdd.c
+	  ssdd.c \
+	  jitterz.c
 
 TARGETS = $(sources:.c=)
 LIBS	= -lrt -lpthread
@@ -47,7 +48,8 @@ MANPAGES = src/cyclictest/cyclictest.8 \
 	   src/queuelat/queuelat.8 \
 	   src/sched_deadline/deadline_test.8 \
 	   src/ssdd/ssdd.8 \
-	   src/sched_deadline/cyclicdeadline.8
+	   src/sched_deadline/cyclicdeadline.8 \
+	   src/jitterz/jitterz.8 \
 
 ifdef PYLIB
 	MANPAGES += src/hwlatdetect/hwlatdetect.8
@@ -96,6 +98,7 @@ VPATH	+= src/hackbench:
 VPATH	+= src/sched_deadline:
 VPATH	+= src/queuelat:	
 VPATH	+= src/ssdd:
+VPATH	+= src/jitterz:
 
 $(OBJDIR)/%.o: %.c | $(OBJDIR)
 	$(CC) -D VERSION=$(VERSION) -c $< $(CFLAGS) $(CPPFLAGS) -o $@
@@ -163,6 +166,9 @@ queuelat: $(OBJDIR)/queuelat.o $(OBJDIR)/librttest.a
 ssdd: $(OBJDIR)/ssdd.o $(OBJDIR)/librttest.a
 	$(CC) $(CFLAGS) $(LDFLAGS) -o $@ $< $(LIBS) $(RTTESTLIB)
 
+jitterz: $(OBJDIR)/jitterz.o
+	$(CC) $(CFLAGS) $(LDFLAGS) -o $@ $< $(LIBS)
+
 %.8.gz: %.8
 	gzip -nc $< > $@
 
diff --git a/src/jitterz/jitterz.8 b/src/jitterz/jitterz.8
new file mode 100644
index 0000000..5b85640
--- /dev/null
+++ b/src/jitterz/jitterz.8
@@ -0,0 +1,39 @@
+.TH JIITERZ 8 "April 1, 2020"
+.SH NAME
+jitterz \- inference of stalls by looking for gaps in executing a tight loop
+.SH SYNOPSIS
+.B jitterz
+.RI "<options>"
+.SH DESCRIPTION
+In a tight loop, measure the time between iterations.
+If the time exceeds a theshold, increment a count in a time
+bucket.  At the end of test print out the buckets.
+.SH OPTIONS
+.B \-c NUM,   \-\-cpu=NUM
+Which cpu to run on
+.br
+.TP
+.B \-\-clock=CLOCK
+select clock
+  0 = CLOCK_MONOTONIC (default)
+  1 = CLOCK_REALTIME
+.br
+.TP
+.B \-d SEC,  \-\-duration=SEC
+Duration of the test in seconds
+.br
+.TP
+.B \-p PRIO,  \-\-priority=PRIO
+Priority of highest prio thread
+.br
+.TP
+.B \-\-policy=NAME
+Policy of measurement thread, where NAME may be one
+of: other, normal, batch, idle, fifo or rr.
+.br
+.TP
+.B \-h, \-\-help
+Display usage
+
+.SH AUTHOR
+jitterz was written by Tom Rix <trix@redhat.com>
diff --git a/src/jitterz/jitterz.c b/src/jitterz/jitterz.c
new file mode 100644
index 0000000..35f8d90
--- /dev/null
+++ b/src/jitterz/jitterz.c
@@ -0,0 +1,400 @@
+// SPDX-License-Identifier: GPL-2.0-only
+/*
+ * jitterz
+ *
+ * Copyright 2019-2020 Tom Rix <trix@redhat.com>
+ *
+ */
+
+#ifndef _GNU_SOURCE
+#define _GNU_SOURCE
+#endif
+#include <stdio.h>
+#include <stdlib.h>
+#include <signal.h>
+#include <stdint.h>
+#include <getopt.h>
+#include <unistd.h>
+#include <inttypes.h>
+#include <time.h>
+#include <string.h>
+#include <errno.h>
+#include <pthread.h>
+#include <sys/time.h>
+#include <sched.h>
+#include <stdbool.h>
+#include <sys/sysinfo.h>
+#include <sys/types.h>
+#include <sys/stat.h>
+#include <sys/mman.h>
+#include <math.h>
+
+#define CPU_DEFAULT 0
+static int cpu;
+static int clocksel;
+static int policy = SCHED_FIFO;
+static int priority = 5;
+
+#define NUMBER_BUCKETS 16
+static struct bucket {
+	uint64_t tick_boundry;
+	uint64_t count;
+	uint64_t time_boundry;
+} b[NUMBER_BUCKETS];
+
+static uint64_t accumulated_lost_ticks;
+static uint64_t delta_time = 500; /* nano sec */
+static uint64_t delta_tick_min; /* first bucket's tick boundry */
+#define RUN_TIME_DEFAULT 60
+static int run_time = RUN_TIME_DEFAULT; /* seconds */
+/* how close do multiple run's calculated frequency have to be valid */
+#define FREQUENCY_TOLERNCE 0.01
+static inline void initialize_buckets(void)
+{
+	int i;
+
+	for (i = 0; i < NUMBER_BUCKETS; i++) {
+		b[i].count = 0;
+		if (i == 0) {
+			b[i].tick_boundry = delta_tick_min;
+			b[i].time_boundry = delta_time;
+		} else {
+			b[i].tick_boundry = b[i - 1].tick_boundry * 2;
+			b[i].time_boundry = b[i - 1].time_boundry * 2;
+		}
+	}
+}
+
+static inline void update_buckets(uint64_t ticks)
+{
+	if (ticks >= delta_tick_min) {
+		int i;
+
+		accumulated_lost_ticks += ticks;
+		for (i = NUMBER_BUCKETS; i > 0; i--) {
+			if (ticks >= b[i - 1].tick_boundry) {
+				b[i - 1].count++;
+				break;
+			}
+		}
+	}
+}
+
+/* Returns clock ticks */
+static inline uint64_t time_stamp_counter(void)
+{
+	uint64_t ret = -1;
+#if defined(__i386__) || defined(__x86_64__)
+	uint32_t l, h;
+
+	__asm__ __volatile__("lfence");
+	__asm__ __volatile__("rdtsc" : "=a"(l), "=d"(h));
+	ret = ((uint64_t)h << 32) | l;
+#else
+	fprintf(stderr,
+		"Add a time_stamp_counter function for your arch here %s:%d\n",
+		__FILE__, __LINE__);
+	exit(1);
+#endif
+	return ret;
+}
+
+static inline int move_to_core()
+{
+	cpu_set_t cpus;
+
+	CPU_ZERO(&cpus);
+	CPU_SET(cpu, &cpus);
+	return sched_setaffinity(0, sizeof(cpus), &cpus);
+}
+
+static inline int set_sched(void)
+{
+	struct sched_param p = { 0 };
+
+	p.sched_priority = priority;
+	return sched_setscheduler(0, policy, &p);
+}
+
+static inline uint64_t read_cpu_current_frequency()
+{
+	uint64_t ret = -1;
+	char path[256];
+	struct stat sb;
+	int i;
+	char *freq[3] = {
+		/* scaling_cur_freq is current kernel /sys file */
+		"scaling_cur_freq"
+		/* old /sys file is cpuinfo_cur_freq */
+		"cpuinfo_cur_freq",
+		/* assumes a busy wait will be run at the max freq */
+		"cpuinfo_max_freq",
+	};
+	for (i = 0; i < 3 && ret == -1; i++) {
+		snprintf(path, 256, "/sys/devices/system/cpu/cpu%d/cpufreq/%s",
+			 cpu, freq[i]);
+		if (!stat(path, &sb)) {
+			FILE *f = 0;
+
+			f = fopen(path, "rt");
+			if (f) {
+				fscanf(f, "%" PRIu64, &ret);
+				/*
+				 * sysfs interface is in units of KHz
+				 * convert to Hz
+				 */
+				ret *= 1000;
+				fclose(f);
+			}
+		}
+	}
+
+	if (ret == -1) {
+		printf("Error reading CPU frequency for core %d\n", cpu);
+		exit(1);
+	}
+	return ret;
+}
+
+/* Print usage information */
+static inline void display_help(int error)
+{
+	printf("jitterz\n");
+	printf("Usage:\n"
+	       "jitterz <options>\n\n"
+	       "-c NUM   --cpu=NUM         which cpu to run on\n"
+	       "         --clock=CLOCK     select clock\n"
+	       "                           0 = CLOCK_MONOTONIC (default)\n"
+	       "                           1 = CLOCK_REALTIME\n"
+	       "-d SEC   --duration=SEC    duration of the test in seconds\n"
+	       "-p PRIO  --priority=PRIO   priority of highest prio thread\n"
+	       "         --policy=NAME     policy of measurement thread, where NAME may be one\n"
+	       "                           of: other, normal, batch, idle, fifo or rr.\n");
+	if (error)
+		exit(EXIT_FAILURE);
+	exit(EXIT_SUCCESS);
+}
+
+static inline char *policyname()
+{
+	char *policystr = "";
+
+	switch (policy) {
+	case SCHED_OTHER:
+		policystr = "other";
+		break;
+	case SCHED_FIFO:
+		policystr = "fifo";
+		break;
+	case SCHED_RR:
+		policystr = "rr";
+		break;
+	case SCHED_BATCH:
+		policystr = "batch";
+		break;
+	case SCHED_IDLE:
+		policystr = "idle";
+		break;
+	}
+	return policystr;
+}
+
+static inline void handlepolicy(char *polname)
+{
+	if (strncasecmp(polname, "other", 5) == 0)
+		policy = SCHED_OTHER;
+	else if (strncasecmp(polname, "batch", 5) == 0)
+		policy = SCHED_BATCH;
+	else if (strncasecmp(polname, "idle", 4) == 0)
+		policy = SCHED_IDLE;
+	else if (strncasecmp(polname, "fifo", 4) == 0)
+		policy = SCHED_FIFO;
+	else if (strncasecmp(polname, "rr", 2) == 0)
+		policy = SCHED_RR;
+	else /* default policy if we don't recognize the request */
+		policy = SCHED_OTHER;
+}
+
+enum option_values {
+	OPT_CPU = 1,
+	OPT_CLOCK,
+	OPT_DURATION,
+	OPT_PRIORITY,
+	OPT_POLICY,
+	OPT_HELP,
+};
+
+/* Process commandline options */
+static inline void process_options(int argc, char *argv[], long max_cpus)
+{
+	for (;;) {
+		int option_index = 0;
+		/*
+		 * Options for getopt
+		 * Ordered alphabetically by single letter name
+		 */
+		static const struct option long_options[] = {
+			{ "clock", required_argument, NULL, OPT_CLOCK },
+			{ "cpu", required_argument, NULL, OPT_CPU },
+			{ "duration", required_argument, NULL, OPT_DURATION },
+			{ "priority", required_argument, NULL, OPT_PRIORITY },
+			{ "policy", required_argument, NULL, OPT_POLICY },
+			{ "help", no_argument, NULL, OPT_HELP },
+			{ NULL, 0, NULL, 0 },
+		};
+		int c = getopt_long(argc, argv, "c:d:hp:", long_options,
+				    &option_index);
+		if (c == -1)
+			break;
+		switch (c) {
+		case 'c':
+		case OPT_CPU:
+			cpu = atoi(optarg);
+			if (cpu >= max_cpus)
+				cpu = CPU_DEFAULT;
+			break;
+		case OPT_CLOCK:
+			clocksel = atoi(optarg);
+			break;
+		case 'd':
+		case OPT_DURATION:
+			run_time = atoi(optarg);
+			if (run_time <= 0)
+				run_time = RUN_TIME_DEFAULT;
+			break;
+		case 'p':
+		case OPT_PRIORITY:
+			priority = atoi(optarg);
+			if (policy != SCHED_FIFO && policy != SCHED_RR)
+				policy = SCHED_FIFO;
+			break;
+		case '?':
+		case OPT_HELP:
+			display_help(0);
+			break;
+		case OPT_POLICY:
+			handlepolicy(optarg);
+			break;
+		}
+	}
+}
+
+int main(int argc, char **argv)
+{
+	long max_cpus = sysconf(_SC_NPROCESSORS_ONLN);
+	struct timespec tvs, tve;
+	double real_duration; /* sec */
+	int i;
+	uint64_t test_tick_start, test_tick_end;
+	static uint64_t frequency_start, frequency_run;
+	double frequency_diff = 0.0; /* unitless */
+
+	process_options(argc, argv, max_cpus);
+
+	/* return of this function must be tested for success */
+	if (move_to_core() != 0) {
+		fprintf(stderr,
+			"Error while setting thread affinity to cpu %d\n", cpu);
+		exit(1);
+	}
+	if (set_sched() != 0) {
+		fprintf(stderr, "Error while setting %s policy, priority %d\n",
+			policyname(), priority);
+		exit(1);
+	}
+
+	if (mlockall(MCL_CURRENT | MCL_FUTURE) != 0) {
+		fprintf(stderr, "Error while locking process memory\n");
+		exit(1);
+	}
+
+	frequency_run = 0;
+	frequency_start = read_cpu_current_frequency();
+	/*
+	 * Start off using the cpu frequency from sysfs
+	 * After each loop
+	 *   calculate the real frequency the whole test
+	 *   run until the real frequency is close enough to the last run
+	 */
+	do {
+	retry:
+		if (frequency_run)
+			frequency_start = frequency_run;
+		delta_tick_min = (delta_time * frequency_start) /
+				 1000000000; /* ticks/nsec */
+
+		accumulated_lost_ticks = 0;
+		initialize_buckets();
+
+		/* record the starting tick and clock time for the test */
+		test_tick_start = time_stamp_counter();
+		clock_gettime(CLOCK_MONOTONIC_RAW, &tvs);
+
+		/* loop over seconds run time */
+		for (i = 0; i < run_time; i++) {
+			uint64_t tick, end_tick, old_tick, tick_overflow;
+
+			end_tick = old_tick = tick = time_stamp_counter();
+			end_tick += frequency_start;
+			/*
+			 * Overflow check
+			 * If end_tick < tick, there will be an overlow
+			 * Add additional second's worth of ticks so
+			 * we do not have to check inside the while loop
+			 * to cover the case that end_tick is close to
+			 * overflowing.
+			 */
+			tick_overflow = end_tick + frequency_start;
+			if (tick_overflow < tick)
+				goto retry;
+
+			/*
+			 * Loop until tick >= end_tick
+			 *
+			 * If the difference in old and current tick
+			 * exceed the minimum tick treshold
+			 *   increment the greatest bucket
+			 *   accumulate total lost ticks
+			 *
+			 * set old_tick to current tick
+			 */
+			while (tick < end_tick) {
+				tick = time_stamp_counter();
+				if (tick == old_tick)
+					continue;
+				update_buckets(tick - old_tick);
+				old_tick = tick;
+			}
+		}
+		/* Record the test ending tick and clock time */
+		test_tick_end = time_stamp_counter();
+		/* overflow */
+		if (test_tick_end < test_tick_start)
+			goto retry;
+		clock_gettime(CLOCK_MONOTONIC_RAW, &tve);
+		/* sec */
+		real_duration = tve.tv_sec - tvs.tv_sec +
+				(tve.tv_nsec - tvs.tv_nsec) / 1e9;
+		/* tick / sec */
+		frequency_run =
+			(test_tick_end - test_tick_start) / (real_duration);
+		frequency_diff = fabs((frequency_run * 1.) - frequency_start) /
+				 frequency_start;
+	} while (frequency_diff > FREQUENCY_TOLERNCE);
+
+	fprintf(stdout, "cutoff time (usec) : stall count \n");
+	for (i = 0; i < NUMBER_BUCKETS; i++) {
+		double t = b[i].time_boundry / 1000000000.; /* sec */
+		if (t < real_duration) {
+			double tb = b[i].time_boundry; /* nsec */
+			fprintf(stdout, "%.1f : %" PRIu64 "\n", tb / 1000.,
+				b[i].count);
+		}
+	}
+
+	printf("Lost time %f out of %d seconds\n",
+	       (double)accumulated_lost_ticks / (double)frequency_start,
+	       run_time);
+
+	return 0;
+}
-- 
2.18.1

Re: [PATCH v2] Import a new test, jitterz

[Tom Rix]

What changed.

A general cleanup of test.

A man page added.

More comments.

Addressing issues, see below.


On 4/1/20 4:02 PM, Thomas Gleixner wrote:
>
> The exact purpose of this is?
>
>> +
>> +#define CHECK_LOST_TIME()					\
>> +	do {							\
>> +		if (d >= dt_min) {				\

This is the update_buckets call, if time difference is greater than a threshold it is added to a bucket.

> Aside of having a \ at the last line, macros which rely on variable
> names at the call site are broken to begin with. What's so magic to hide
> this in a macro instead of writing a proper function?

This was changed to a function.

>> +static inline uint64_t tsc(void)
>> +{
>> +	uint64_t ret = 0;
>> +	uint32_t l, h;
>> +
>> +	__asm__ __volatile__("lfence");
>> +	__asm__ __volatile__("rdtsc" : "=a"(l), "=d"(h));
>> +	ret = ((uint64_t)h << 32) | l;
>> +	return ret;
>> +}
> Having x86 specific code in a generic test suite is a non starter.
If-def added to build of x86, else provide a runtime error.
> +	char *freq[2] = {
> +		"cpuinfo_cur_freq",
> +		/* assumes a busy wait will be run at the max freq */
> Assumptions in tools which are meant to provide useful output are really
> not useful at all.

These frequencies are only starting points, the test recalculates the frequency at runtime.


>> +			if (f) {
>> +				fscanf(f, "%lu", &fs);
> That definitely has never seen a 32bit compile.
Changed to use PRIu64 macro and verified on i386 compile.
> +
> +	if (fs == (uint64_t) -1) {
> So here you have a typecast but at the place where this is initialized
> this is not required, right?
Typecast removed.
>
>> +	return 0;
> As the above is completely unreadable gibberish I can only assume that I
> wasted time staring at a well done April 1st joke :)

Rewrite + comments should make the understanding the main loop easier.

Tom

Re: [PATCH v2] Import a new test, jitterz

[Sebastian Andrzej Siewior]

On 2020-04-18 07:14:49 [-0700], trix@redhat.com wrote:
> --- /dev/null
> +++ b/src/jitterz/jitterz.c
> @@ -0,0 +1,400 @@
…
> +/*
> + * jitterz
> + *
> + * Copyright 2019-2020 Tom Rix <trix@redhat.com>
> + *
> + */
> +
> +#ifndef _GNU_SOURCE
> +#define _GNU_SOURCE
> +#endif

in general there is no need of that ifndef and this should be taken care
by the build system (and refuse the build if _GNU_SOURCE makes no
difference/ is not available). And then include the config.h (or so)
first header file. 
In rt-tests, the Makefile already adds this define to the CFLAGS.

…
> +/* Returns clock ticks */
> +static inline uint64_t time_stamp_counter(void)
> +{
> +	uint64_t ret = -1;
> +#if defined(__i386__) || defined(__x86_64__)
> +	uint32_t l, h;
> +
> +	__asm__ __volatile__("lfence");
> +	__asm__ __volatile__("rdtsc" : "=a"(l), "=d"(h));
> +	ret = ((uint64_t)h << 32) | l;
> +#else
> +	fprintf(stderr,
> +		"Add a time_stamp_counter function for your arch here %s:%d\n",
> +		__FILE__, __LINE__);
> +	exit(1);
> +#endif
> +	return ret;
> +}

I remember I complained about this in `queuelat' and it ended nowhere
once it got merged.
To repeat my question: Is there a reason not to use clock_gettime()?
With VDSO there should be hardly any difference between this and
clock_gettime().

Sebastian

Re: [PATCH v2] Import a new test, jitterz

[John Kacur]

[-- Attachment #1: Type: text/plain, Size: 1520 bytes --]



On Mon, 20 Apr 2020, Sebastian Andrzej Siewior wrote:

> On 2020-04-18 07:14:49 [-0700], trix@redhat.com wrote:
> > --- /dev/null
> > +++ b/src/jitterz/jitterz.c
> > @@ -0,0 +1,400 @@
> …
> > +/*
> > + * jitterz
> > + *
> > + * Copyright 2019-2020 Tom Rix <trix@redhat.com>
> > + *
> > + */
> > +
> > +#ifndef _GNU_SOURCE
> > +#define _GNU_SOURCE
> > +#endif
> 
> in general there is no need of that ifndef and this should be taken care
> by the build system (and refuse the build if _GNU_SOURCE makes no
> difference/ is not available). And then include the config.h (or so)
> first header file. 
> In rt-tests, the Makefile already adds this define to the CFLAGS.
> 
> …
> > +/* Returns clock ticks */
> > +static inline uint64_t time_stamp_counter(void)
> > +{
> > +	uint64_t ret = -1;
> > +#if defined(__i386__) || defined(__x86_64__)
> > +	uint32_t l, h;
> > +
> > +	__asm__ __volatile__("lfence");
> > +	__asm__ __volatile__("rdtsc" : "=a"(l), "=d"(h));
> > +	ret = ((uint64_t)h << 32) | l;
> > +#else
> > +	fprintf(stderr,
> > +		"Add a time_stamp_counter function for your arch here %s:%d\n",
> > +		__FILE__, __LINE__);
> > +	exit(1);
> > +#endif
> > +	return ret;
> > +}
> 
> I remember I complained about this in `queuelat' and it ended nowhere
> once it got merged.
> To repeat my question: Is there a reason not to use clock_gettime()?
> With VDSO there should be hardly any difference between this and
> clock_gettime().

I would agree with Sebastian there Tom, also easier to maintain.

Thanks

John

Re: [PATCH v2] Import a new test, jitterz

[John Kacur]

On Sat, 18 Apr 2020, trix@redhat.com wrote:

> From: Tom Rix <trix@redhat.com>
> 
> jitterz is a program for measuring system jitter.
> 
> It is a rewrite of sysjitter
> https://github.com/alexeiz/sysjitter
> 
> The upstream location of jitterz is
> https://github.com/trixirt/jitterz
> 
> Signed-off-by: Tom Rix <trix@redhat.com>
> ---
>  Makefile              |  10 +-
>  src/jitterz/jitterz.8 |  39 ++++
>  src/jitterz/jitterz.c | 400 ++++++++++++++++++++++++++++++++++++++++++
>  3 files changed, 447 insertions(+), 2 deletions(-)
>  create mode 100644 src/jitterz/jitterz.8
>  create mode 100644 src/jitterz/jitterz.c
> 
> diff --git a/Makefile b/Makefile
> index 05fc5ed..3a88a5f 100644
> --- a/Makefile
> +++ b/Makefile
> @@ -17,7 +17,8 @@ sources = cyclictest.c \
>  	  cyclicdeadline.c \
>  	  deadline_test.c \
>  	  queuelat.c \
> -	  ssdd.c
> +	  ssdd.c \
> +	  jitterz.c
>  
>  TARGETS = $(sources:.c=)
>  LIBS	= -lrt -lpthread
> @@ -47,7 +48,8 @@ MANPAGES = src/cyclictest/cyclictest.8 \
>  	   src/queuelat/queuelat.8 \
>  	   src/sched_deadline/deadline_test.8 \
>  	   src/ssdd/ssdd.8 \
> -	   src/sched_deadline/cyclicdeadline.8
> +	   src/sched_deadline/cyclicdeadline.8 \
> +	   src/jitterz/jitterz.8 \
>  
>  ifdef PYLIB
>  	MANPAGES += src/hwlatdetect/hwlatdetect.8
> @@ -96,6 +98,7 @@ VPATH	+= src/hackbench:
>  VPATH	+= src/sched_deadline:
>  VPATH	+= src/queuelat:	
>  VPATH	+= src/ssdd:
> +VPATH	+= src/jitterz:
>  
>  $(OBJDIR)/%.o: %.c | $(OBJDIR)
>  	$(CC) -D VERSION=$(VERSION) -c $< $(CFLAGS) $(CPPFLAGS) -o $@
> @@ -163,6 +166,9 @@ queuelat: $(OBJDIR)/queuelat.o $(OBJDIR)/librttest.a
>  ssdd: $(OBJDIR)/ssdd.o $(OBJDIR)/librttest.a
>  	$(CC) $(CFLAGS) $(LDFLAGS) -o $@ $< $(LIBS) $(RTTESTLIB)
>  
> +jitterz: $(OBJDIR)/jitterz.o
> +	$(CC) $(CFLAGS) $(LDFLAGS) -o $@ $< $(LIBS)
> +
>  %.8.gz: %.8
>  	gzip -nc $< > $@
>  
> diff --git a/src/jitterz/jitterz.8 b/src/jitterz/jitterz.8
> new file mode 100644
> index 0000000..5b85640
> --- /dev/null
> +++ b/src/jitterz/jitterz.8
> @@ -0,0 +1,39 @@
> +.TH JIITERZ 8 "April 1, 2020"
> +.SH NAME
> +jitterz \- inference of stalls by looking for gaps in executing a tight loop
> +.SH SYNOPSIS
> +.B jitterz
> +.RI "<options>"
> +.SH DESCRIPTION
> +In a tight loop, measure the time between iterations.
> +If the time exceeds a theshold, increment a count in a time
> +bucket.  At the end of test print out the buckets.
> +.SH OPTIONS
> +.B \-c NUM,   \-\-cpu=NUM
> +Which cpu to run on
> +.br
> +.TP
> +.B \-\-clock=CLOCK
> +select clock
> +  0 = CLOCK_MONOTONIC (default)
> +  1 = CLOCK_REALTIME
> +.br
> +.TP
> +.B \-d SEC,  \-\-duration=SEC
> +Duration of the test in seconds
> +.br
> +.TP
> +.B \-p PRIO,  \-\-priority=PRIO
> +Priority of highest prio thread
> +.br
> +.TP
> +.B \-\-policy=NAME
> +Policy of measurement thread, where NAME may be one
> +of: other, normal, batch, idle, fifo or rr.
> +.br
> +.TP
> +.B \-h, \-\-help
> +Display usage
> +
> +.SH AUTHOR
> +jitterz was written by Tom Rix <trix@redhat.com>
> diff --git a/src/jitterz/jitterz.c b/src/jitterz/jitterz.c
> new file mode 100644
> index 0000000..35f8d90
> --- /dev/null
> +++ b/src/jitterz/jitterz.c
> @@ -0,0 +1,400 @@
> +// SPDX-License-Identifier: GPL-2.0-only
> +/*
> + * jitterz
> + *
> + * Copyright 2019-2020 Tom Rix <trix@redhat.com>
> + *
> + */

Should the manpage mention that the original idea comes from sysjitter?
While I'm asking that, just to play devil's advocate, why are we not just
forking sysjitter and adapting it to our needs? What advantage to we get
by re-implemnting this?

> +
> +#ifndef _GNU_SOURCE
> +#define _GNU_SOURCE
> +#endif
> +#include <stdio.h>
> +#include <stdlib.h>
> +#include <signal.h>
> +#include <stdint.h>
> +#include <getopt.h>
> +#include <unistd.h>
> +#include <inttypes.h>
> +#include <time.h>
> +#include <string.h>
> +#include <errno.h>
> +#include <pthread.h>
> +#include <sys/time.h>
> +#include <sched.h>
> +#include <stdbool.h>
> +#include <sys/sysinfo.h>
> +#include <sys/types.h>
> +#include <sys/stat.h>
> +#include <sys/mman.h>
> +#include <math.h>
> +
> +#define CPU_DEFAULT 0
> +static int cpu;
> +static int clocksel;
> +static int policy = SCHED_FIFO;
> +static int priority = 5;
> +
> +#define NUMBER_BUCKETS 16
> +static struct bucket {
> +	uint64_t tick_boundry;
> +	uint64_t count;
> +	uint64_t time_boundry;
> +} b[NUMBER_BUCKETS];
> +
> +static uint64_t accumulated_lost_ticks;
> +static uint64_t delta_time = 500; /* nano sec */
> +static uint64_t delta_tick_min; /* first bucket's tick boundry */
> +#define RUN_TIME_DEFAULT 60
> +static int run_time = RUN_TIME_DEFAULT; /* seconds */
> +/* how close do multiple run's calculated frequency have to be valid */
> +#define FREQUENCY_TOLERNCE 0.01
> +static inline void initialize_buckets(void)
> +{
> +	int i;
> +
> +	for (i = 0; i < NUMBER_BUCKETS; i++) {
> +		b[i].count = 0;
> +		if (i == 0) {
> +			b[i].tick_boundry = delta_tick_min;
> +			b[i].time_boundry = delta_time;
> +		} else {
> +			b[i].tick_boundry = b[i - 1].tick_boundry * 2;
> +			b[i].time_boundry = b[i - 1].time_boundry * 2;
> +		}
> +	}
> +}
> +
> +static inline void update_buckets(uint64_t ticks)
> +{
> +	if (ticks >= delta_tick_min) {
> +		int i;
> +
> +		accumulated_lost_ticks += ticks;
> +		for (i = NUMBER_BUCKETS; i > 0; i--) {
> +			if (ticks >= b[i - 1].tick_boundry) {
> +				b[i - 1].count++;
> +				break;
> +			}
> +		}
> +	}
> +}
> +
> +/* Returns clock ticks */
> +static inline uint64_t time_stamp_counter(void)
> +{
> +	uint64_t ret = -1;
> +#if defined(__i386__) || defined(__x86_64__)
> +	uint32_t l, h;
> +
> +	__asm__ __volatile__("lfence");
> +	__asm__ __volatile__("rdtsc" : "=a"(l), "=d"(h));
> +	ret = ((uint64_t)h << 32) | l;
> +#else
> +	fprintf(stderr,
> +		"Add a time_stamp_counter function for your arch here %s:%d\n",
> +		__FILE__, __LINE__);
> +	exit(1);
> +#endif
> +	return ret;
> +}
> +
> +static inline int move_to_core()
> +{
> +	cpu_set_t cpus;
> +
> +	CPU_ZERO(&cpus);
> +	CPU_SET(cpu, &cpus);
> +	return sched_setaffinity(0, sizeof(cpus), &cpus);
> +}
> +
> +static inline int set_sched(void)
> +{
> +	struct sched_param p = { 0 };
> +
> +	p.sched_priority = priority;
> +	return sched_setscheduler(0, policy, &p);
> +}
> +
> +static inline uint64_t read_cpu_current_frequency()
> +{
> +	uint64_t ret = -1;
> +	char path[256];
> +	struct stat sb;
> +	int i;
> +	char *freq[3] = {
> +		/* scaling_cur_freq is current kernel /sys file */
> +		"scaling_cur_freq"
> +		/* old /sys file is cpuinfo_cur_freq */
> +		"cpuinfo_cur_freq",
> +		/* assumes a busy wait will be run at the max freq */
> +		"cpuinfo_max_freq",
> +	};
> +	for (i = 0; i < 3 && ret == -1; i++) {
> +		snprintf(path, 256, "/sys/devices/system/cpu/cpu%d/cpufreq/%s",
> +			 cpu, freq[i]);
> +		if (!stat(path, &sb)) {
> +			FILE *f = 0;
> +
> +			f = fopen(path, "rt");
> +			if (f) {
> +				fscanf(f, "%" PRIu64, &ret);
> +				/*
> +				 * sysfs interface is in units of KHz
> +				 * convert to Hz
> +				 */
> +				ret *= 1000;
> +				fclose(f);
> +			}
> +		}
> +	}
> +
> +	if (ret == -1) {
> +		printf("Error reading CPU frequency for core %d\n", cpu);
> +		exit(1);
> +	}
> +	return ret;
> +}
> +
> +/* Print usage information */
> +static inline void display_help(int error)
> +{
> +	printf("jitterz\n");
> +	printf("Usage:\n"
> +	       "jitterz <options>\n\n"
> +	       "-c NUM   --cpu=NUM         which cpu to run on\n"
> +	       "         --clock=CLOCK     select clock\n"
> +	       "                           0 = CLOCK_MONOTONIC (default)\n"
> +	       "                           1 = CLOCK_REALTIME\n"
> +	       "-d SEC   --duration=SEC    duration of the test in seconds\n"
> +	       "-p PRIO  --priority=PRIO   priority of highest prio thread\n"
> +	       "         --policy=NAME     policy of measurement thread, where NAME may be one\n"
> +	       "                           of: other, normal, batch, idle, fifo or rr.\n");
> +	if (error)
> +		exit(EXIT_FAILURE);
> +	exit(EXIT_SUCCESS);
> +}
> +
> +static inline char *policyname()
> +{
> +	char *policystr = "";
> +
> +	switch (policy) {
> +	case SCHED_OTHER:
> +		policystr = "other";
> +		break;
> +	case SCHED_FIFO:
> +		policystr = "fifo";
> +		break;
> +	case SCHED_RR:
> +		policystr = "rr";
> +		break;
> +	case SCHED_BATCH:
> +		policystr = "batch";
> +		break;
> +	case SCHED_IDLE:
> +		policystr = "idle";
> +		break;
> +	}
> +	return policystr;
> +}
> +
> +static inline void handlepolicy(char *polname)
> +{
> +	if (strncasecmp(polname, "other", 5) == 0)
> +		policy = SCHED_OTHER;
> +	else if (strncasecmp(polname, "batch", 5) == 0)
> +		policy = SCHED_BATCH;
> +	else if (strncasecmp(polname, "idle", 4) == 0)
> +		policy = SCHED_IDLE;
> +	else if (strncasecmp(polname, "fifo", 4) == 0)
> +		policy = SCHED_FIFO;
> +	else if (strncasecmp(polname, "rr", 2) == 0)
> +		policy = SCHED_RR;
> +	else /* default policy if we don't recognize the request */
> +		policy = SCHED_OTHER;
> +}
> +
> +enum option_values {
> +	OPT_CPU = 1,
> +	OPT_CLOCK,
> +	OPT_DURATION,
> +	OPT_PRIORITY,
> +	OPT_POLICY,
> +	OPT_HELP,
> +};
> +
> +/* Process commandline options */
> +static inline void process_options(int argc, char *argv[], long max_cpus)
> +{
> +	for (;;) {
> +		int option_index = 0;
> +		/*
> +		 * Options for getopt
> +		 * Ordered alphabetically by single letter name
> +		 */
> +		static const struct option long_options[] = {
> +			{ "clock", required_argument, NULL, OPT_CLOCK },
> +			{ "cpu", required_argument, NULL, OPT_CPU },
> +			{ "duration", required_argument, NULL, OPT_DURATION },
> +			{ "priority", required_argument, NULL, OPT_PRIORITY },
> +			{ "policy", required_argument, NULL, OPT_POLICY },
> +			{ "help", no_argument, NULL, OPT_HELP },
> +			{ NULL, 0, NULL, 0 },
> +		};
> +		int c = getopt_long(argc, argv, "c:d:hp:", long_options,
> +				    &option_index);
> +		if (c == -1)
> +			break;
> +		switch (c) {
> +		case 'c':
> +		case OPT_CPU:
> +			cpu = atoi(optarg);
> +			if (cpu >= max_cpus)
> +				cpu = CPU_DEFAULT;
> +			break;
> +		case OPT_CLOCK:
> +			clocksel = atoi(optarg);
> +			break;
> +		case 'd':
> +		case OPT_DURATION:
> +			run_time = atoi(optarg);
> +			if (run_time <= 0)
> +				run_time = RUN_TIME_DEFAULT;
> +			break;
> +		case 'p':
> +		case OPT_PRIORITY:
> +			priority = atoi(optarg);
> +			if (policy != SCHED_FIFO && policy != SCHED_RR)
> +				policy = SCHED_FIFO;
> +			break;
> +		case '?':
> +		case OPT_HELP:
> +			display_help(0);
> +			break;
> +		case OPT_POLICY:
> +			handlepolicy(optarg);
> +			break;
> +		}
> +	}
> +}
> +
> +int main(int argc, char **argv)
> +{
> +	long max_cpus = sysconf(_SC_NPROCESSORS_ONLN);
> +	struct timespec tvs, tve;
> +	double real_duration; /* sec */
> +	int i;
> +	uint64_t test_tick_start, test_tick_end;
> +	static uint64_t frequency_start, frequency_run;
> +	double frequency_diff = 0.0; /* unitless */
> +
> +	process_options(argc, argv, max_cpus);
> +
> +	/* return of this function must be tested for success */
> +	if (move_to_core() != 0) {
> +		fprintf(stderr,
> +			"Error while setting thread affinity to cpu %d\n", cpu);
> +		exit(1);
> +	}
> +	if (set_sched() != 0) {
> +		fprintf(stderr, "Error while setting %s policy, priority %d\n",
> +			policyname(), priority);
> +		exit(1);
> +	}
> +
> +	if (mlockall(MCL_CURRENT | MCL_FUTURE) != 0) {
> +		fprintf(stderr, "Error while locking process memory\n");
> +		exit(1);
> +	}
> +
> +	frequency_run = 0;
> +	frequency_start = read_cpu_current_frequency();
> +	/*
> +	 * Start off using the cpu frequency from sysfs
> +	 * After each loop
> +	 *   calculate the real frequency the whole test
> +	 *   run until the real frequency is close enough to the last run
> +	 */
> +	do {
> +	retry:
> +		if (frequency_run)
> +			frequency_start = frequency_run;
> +		delta_tick_min = (delta_time * frequency_start) /
> +				 1000000000; /* ticks/nsec */
> +
> +		accumulated_lost_ticks = 0;
> +		initialize_buckets();
> +
> +		/* record the starting tick and clock time for the test */
> +		test_tick_start = time_stamp_counter();
> +		clock_gettime(CLOCK_MONOTONIC_RAW, &tvs);
> +
> +		/* loop over seconds run time */
> +		for (i = 0; i < run_time; i++) {
> +			uint64_t tick, end_tick, old_tick, tick_overflow;
> +
> +			end_tick = old_tick = tick = time_stamp_counter();
> +			end_tick += frequency_start;
> +			/*
> +			 * Overflow check
> +			 * If end_tick < tick, there will be an overlow
> +			 * Add additional second's worth of ticks so
> +			 * we do not have to check inside the while loop
> +			 * to cover the case that end_tick is close to
> +			 * overflowing.
> +			 */
> +			tick_overflow = end_tick + frequency_start;
> +			if (tick_overflow < tick)
> +				goto retry;
> +
> +			/*
> +			 * Loop until tick >= end_tick
> +			 *
> +			 * If the difference in old and current tick
> +			 * exceed the minimum tick treshold
> +			 *   increment the greatest bucket
> +			 *   accumulate total lost ticks
> +			 *
> +			 * set old_tick to current tick
> +			 */
> +			while (tick < end_tick) {
> +				tick = time_stamp_counter();
> +				if (tick == old_tick)
> +					continue;
> +				update_buckets(tick - old_tick);
> +				old_tick = tick;
> +			}
> +		}
> +		/* Record the test ending tick and clock time */
> +		test_tick_end = time_stamp_counter();
> +		/* overflow */
> +		if (test_tick_end < test_tick_start)
> +			goto retry;
> +		clock_gettime(CLOCK_MONOTONIC_RAW, &tve);
> +		/* sec */
> +		real_duration = tve.tv_sec - tvs.tv_sec +
> +				(tve.tv_nsec - tvs.tv_nsec) / 1e9;
> +		/* tick / sec */
> +		frequency_run =
> +			(test_tick_end - test_tick_start) / (real_duration);
> +		frequency_diff = fabs((frequency_run * 1.) - frequency_start) /
> +				 frequency_start;
> +	} while (frequency_diff > FREQUENCY_TOLERNCE);
> +
> +	fprintf(stdout, "cutoff time (usec) : stall count \n");
> +	for (i = 0; i < NUMBER_BUCKETS; i++) {
> +		double t = b[i].time_boundry / 1000000000.; /* sec */
> +		if (t < real_duration) {
> +			double tb = b[i].time_boundry; /* nsec */
> +			fprintf(stdout, "%.1f : %" PRIu64 "\n", tb / 1000.,
> +				b[i].count);
> +		}
> +	}
> +
> +	printf("Lost time %f out of %d seconds\n",
> +	       (double)accumulated_lost_ticks / (double)frequency_start,
> +	       run_time);
> +
> +	return 0;
> +}
> -- 
> 2.18.1
> 
> 

Re: [PATCH v2] Import a new test, jitterz

[Tom Rix]

John,
>> + *
>> + * Copyright 2019-2020 Tom Rix <trix@redhat.com>
>> + *
>> + */
> Should the manpage mention that the original idea comes from sysjitter?
> While I'm asking that, just to play devil's advocate, why are we not just
> forking sysjitter and adapting it to our needs? What advantage to we get
> by re-implemnting this?

sysjitter is not a well known nor a well supported tool, the attribution in the commit log is enough.

jitterz was started because of limitations in sysjitter. So the effort would be to fork and address those limitations and upstream.

Tom

Re: [PATCH v2] Import a new test, jitterz

[Thomas Gleixner]

Tom,

trix@redhat.com writes:
> From: Tom Rix <trix@redhat.com>

it seems you are serious about this.

> jitterz is a program for measuring system jitter.

Aside of that not being accurate, there is neither a proper description
of the functionality nor a reasoning why this is useful and should
therefore be part of rt-tests.

> diff --git a/src/jitterz/jitterz.8 b/src/jitterz/jitterz.8
> new file mode 100644
> index 0000000..5b85640
> --- /dev/null
> +++ b/src/jitterz/jitterz.8
> @@ -0,0 +1,39 @@
> +.TH JIITERZ 8 "April 1, 2020"
> +.SH NAME
> +jitterz \- inference of stalls by looking for gaps in executing a tight loop
> +.SH SYNOPSIS
> +.B jitterz
> +.RI "<options>"
> +.SH DESCRIPTION
> +In a tight loop, measure the time between iterations.
> +If the time exceeds a theshold, increment a count in a time
> +bucket.  At the end of test print out the buckets.

Jitter is the deviation from true periodicity of a periodic event.

But that's not what you are measuring here. You try to find gaps in
tight loop execution, which is something completely different.

Now again the question is what's the purpose and the value of this
measurement?

> +/* Returns clock ticks */
> +static inline uint64_t time_stamp_counter(void)
> +{
> +	uint64_t ret = -1;
> +#if defined(__i386__) || defined(__x86_64__)
> +	uint32_t l, h;

First of all. What's wrong with using clock_gettime() ?

> +	__asm__ __volatile__("lfence");
> +	__asm__ __volatile__("rdtsc" : "=a"(l), "=d"(h));

Aside of that x86-ism here, what guarantees that the CPU has lfence?

> +	ret = ((uint64_t)h << 32) | l;
> +#else
> +	fprintf(stderr,
> +		"Add a time_stamp_counter function for your arch here %s:%d\n",
> +		__FILE__, __LINE__);

This is brilliant. You know already at compile time that this can't
work, but instead of failing the build you print an error at runtime.

Thanks,

        tglx