Improve time measurement

controller/controller/controller_sample.c

@@ -35,6 +35,7 @@
 #include <sched.h>
 #include <dirent.h>
 #include <ctype.h>
+#include <inttypes.h>
 
 #include <controller/controller_block.h>
 #include <controller/controller_sample.h>
@@ -50,9 +51,9 @@ static pthread_t controller_sample_thread;
 static bool controller_sample_thread_running = false;
 
 struct sample_timing {
-	double min;
-	double max;
-	double avg;
+	uint64_t min;
+	uint64_t max;
+	uint64_t sum;
 	long long n;
 	char *name;
 };
@@ -90,31 +91,21 @@ static void sample_timing_init(struct sample_timing *st, char *name)
 {
 	memset(st, 0, sizeof(struct sample_timing));
 	st->name = name;
+	st->min = 10000000000ull;
 }
 
-static void sample_timing_add(struct sample_timing *st, 
-    struct timespec *t1, struct timespec *t2)
+static void sample_timing_add(struct sample_timing *st, uint64_t t1, uint64_t t2)
 {
-	double t;
+	int64_t t;
 	
-	t = t2->tv_nsec * 1.0 - t1->tv_nsec * 1.0;
-	t += (t2->tv_sec - t1->tv_sec) * 1000000000;
-
-	if (st->n == 0) {
-		st->min = t;
-		st->max = t;
-		st->avg = t;
-		st->n = 1;
-		return;
-	}
+	t = t2 - t1;
 	
 	if (t > st->max)
 		st->max = t;
 	if (t < st->min)
 		st->min = t;
-	st->avg = st->avg * st->n + t;
+	st->sum += t;
 	st->n++;
-	st->avg /= st->n * 1.0;
 
 	return;
 }
@@ -134,27 +125,22 @@ static ssize_t sample_timing_snprintf(struct sample_timing *st,
     char *dest, size_t n)
 {
 	return snprintf(dest, n, "%s\t%.3f\t%.3f\t%.3f",
-	    st->name,
-	    st->min / 1000.0, st->avg / 1000.0, st->max / 1000.0);
+	    st->name, 
+	    (double)st->min/1000.0, 
+	    ((double)st->sum / 1000.0) / (double)st->n,
+	    (double)st->max/1000.0);
 }
 
 
-static int sample_timing_sane(struct timespec *t_exp, struct timespec *t_act)
+static int sample_timing_sane(uint64_t t_exp, uint64_t t_act)
 {
-	long s_diff;
-	long n_diff;
+	uint64_t n_diff;
 	
-	s_diff = t_act->tv_sec - t_exp->tv_sec;
+	if (t_exp > t_act)
+		n_diff = t_exp - t_act;
+	else
+		n_diff = t_act - t_exp;
 	
-	if (s_diff < 0) {
-		return -1;
-	}
-	if (s_diff > 1) {
-		return 1;
-	}
-
-	n_diff = s_diff * 1000 * 1000 * 1000;
-	n_diff += t_act->tv_nsec - t_exp->tv_nsec;
 	if (n_diff > nsec_interval * 10) {
 		return 1;
 	}
@@ -297,6 +283,15 @@ static void wait_next(struct timespec *t)
 #endif
 }
 
+static uint64_t timestamp(void)
+{
+	struct timespec t;
+	
+	clock_gettime(sample_clock, &t);
+
+	return (uint64_t)t.tv_sec * 1000000000 + (uint64_t)t.tv_nsec;
+}
+
 /*
 	This thread should be realtime....
  */
@@ -304,9 +299,10 @@ static void *sample_thread(void *arg)
 {
 	struct timespec t;
 	struct sched_param param;
-	struct timespec t_start;
-	struct timespec t_io;
-	struct timespec t_end;
+	uint64_t t_trig;
+	uint64_t t_start;
+	uint64_t t_io;
+	uint64_t t_end;
 	param.sched_priority = 99;
 	sigset_t sigset;
 	struct sigaction sigact;
@@ -338,8 +334,9 @@ static void *sample_thread(void *arg)
 
 	clock_gettime(sample_clock, &t);
 	
-	t.tv_nsec = 0;
-	t.tv_sec++;
+	t.tv_nsec += nsec_interval - 1;
+	t.tv_nsec -= t.tv_nsec % nsec_interval;
+	tsnorm(&t);
 
 	while (1) {
 		/* Pre sample stuff: */
@@ -348,8 +345,9 @@ static void *sample_thread(void *arg)
 		t.tv_nsec += nsec_interval;
 		tsnorm(&t);
 	
-		controller_time_nseconds = (uint64_t)t.tv_sec * 1000000000;
-		controller_time_nseconds += t.tv_nsec;
+		t_trig = (uint64_t)t.tv_sec * 1000000000;
+		t_trig += t.tv_nsec;
+		controller_time_nseconds = t_trig;
 		controller_time_seconds = t.tv_sec;
 		controller_time_samplenr = t.tv_nsec / nsec_interval;
 
@@ -357,36 +355,35 @@ static void *sample_thread(void *arg)
 		   (Internal timer or external interrupt) */
 		wait_next(&t);
 
-		clock_gettime(sample_clock, &t_start);
+		t_start = timestamp();
 
 		/* Do sample stuff */
 		controller_block_calculate();
 		
-		clock_gettime(sample_clock, &t_io);
+		t_io = timestamp();
 		
 		controller_block_trace();
 		controller_block_param_handle();
 		
-		clock_gettime(sample_clock, &t_end);
+		t_end = timestamp();
 		
-		if (sample_timing_diff_nsec(&t, &t_end) > nsec_interval) {
+		if (t_end - t_trig > nsec_interval) {
 			controller_sampleoverruns++;
 		}
-		if (sample_timing_sane(&t, &t_start)) {
+		if (sample_timing_sane(t_trig, t_start)) {
 			log_send(LOG_T_ERROR, 
-			    "Time sanity check triggered: %lld.%09ld %lld.%09ld",
-			    (long long)t.tv_sec, t.tv_nsec, 
-			    (long long)t_start.tv_sec, t_start.tv_nsec);
-			t.tv_sec = t_start.tv_sec;
-			t.tv_nsec = (t_start.tv_nsec / nsec_interval) * nsec_interval;
+			    "Time sanity check triggered: %" PRIu64 " nsec difference",
+			    t_start - t_trig);
+			clock_gettime(sample_clock, &t);
+			t.tv_nsec -= (t.tv_nsec % nsec_interval);
 			log_send(LOG_T_WARNING,
 			    "Using current time for next sampe: %lld.%09ld",
 			    (long long)t.tv_sec, t.tv_nsec);
 		} else {
-			sample_timing_add(&st_start, &t, &t_start);
-			sample_timing_add(&st_io, &t_start, &t_io);
-			sample_timing_add(&st_end, &t, &t_end);
-			sample_timing_add(&st_sample, &t_start, &t_end);
+			sample_timing_add(&st_start, t_trig, t_start);
+			sample_timing_add(&st_io, t_start, t_io);
+			sample_timing_add(&st_end, t_trig, t_end);
+			sample_timing_add(&st_sample, t_start, t_end);
 		}
 		alarm(1);
 	}