timebend option: allow to specify how fast time passes

This is particularly useful when replaying vsl files (-r option).

The new -B option specifies a time factor limiting the speed at which
the log is being read. It can also be halved/doubled using the < and >
keys at runtime.

Conflicts:
	bin/varnishhist/varnishhist.c

bin/varnishhist/Makefile.am

@@ -19,6 +19,7 @@ varnishhist_SOURCES = varnishhist.c \
 varnishhist_LDADD = \
 	$(top_builddir)/lib/libvarnishcompat/libvarnishcompat.la \
 	$(top_builddir)/lib/libvarnishapi/libvarnishapi.la \
+	$(top_builddir)/lib/libvarnish/libvarnish.la \
 	-lm \
 	@CURSES_LIB@ ${RT_LIBS} ${PTHREAD_LIBS}
 

bin/varnishhist/varnishhist.c

@@ -54,6 +54,7 @@
 #include "vas.h"
 #include "vcs.h"
 #include "vut.h"
+#include "vtim.h"
 
 #define HIST_N 2000 /* how far back we remember */
 #define HIST_RES 100 /* bucket resolution */
@@ -76,7 +77,9 @@ static unsigned *bucket_miss;
 static unsigned *bucket_hit;
 static char *format;
 static int match_tag;
-
+double timebend = 0, t0;
+double vsl_t0 = 0, vsl_to, vsl_ts = 0;
+pthread_cond_t timebend_cv;
 static double log_ten;
 
 static int scales[] = {
@@ -212,13 +215,21 @@ update(void)
 			max = bm[l] + bh[l];
 	}
 
-	/* scale */
+	/* scale,time */
 	assert(LINES - 3 >= 0);
 	for (i = 0; max / scales[i] > (unsigned)(LINES - 3); ++i)
 		/* nothing */ ;
 	scale = scales[i];
 
-	mvprintw(0, 0, "1:%d, n = %d, d = %g", scale, nhist, delay);
+	if (vsl_t0 > 0) {
+		char t[VTIM_FORMAT_SIZE];
+		VTIM_format(vsl_ts, t);
+
+		mvprintw(0, 0, "1:%d, n = %d, d = %g @ %s x %g",
+		scale, nhist, delay, t, timebend);
+	} else {
+		mvprintw(0, 0, "1:%d, n = %d, d = %g", scale, nhist, delay);
+	}
 
 	for (j = 2; j < LINES - 3; j+=5)
 		mvprintw(j, 0, "%d_", (LINES - 3 - j) * scale);
@@ -234,6 +245,25 @@ update(void)
 	refresh();
 }
 
+inline static void
+upd_vsl_ts(const char *p)
+{
+	double t;
+
+	if (timebend == 0)
+		return;
+
+	p = strchr(p, ' ');
+
+	if (p == NULL)
+		return;
+
+	t = strtod(p + 1, NULL);
+
+	if (t > vsl_ts)
+		vsl_ts = t;
+}
+
 static int /*__match_proto__ (VSLQ_dispatch_f)*/
 accumulate(struct VSL_data *vsl, struct VSL_transaction * const pt[],
 	void *priv)
@@ -242,6 +272,8 @@ accumulate(struct VSL_data *vsl, struct VSL_transaction * const pt[],
 	unsigned u;
 	double value;
 	struct VSL_transaction *tr;
+	double t;
+	const char *tsp;
 
 	(void)vsl;
 	(void)priv;
@@ -254,7 +286,20 @@ accumulate(struct VSL_data *vsl, struct VSL_transaction * const pt[],
 		hit = 0;
 		skip = 0;
 		match = 0;
-		while (skip == 0 && 1 == VSL_Next(tr->c)) {
+		tsp = NULL;
+		while (skip == 0) {
+			i = VSL_Next(tr->c);
+			if (i == -3) {
+				// overrun - need to skip forward
+				pthread_mutex_lock(&mtx);
+				vsl_to = vsl_t0 = vsl_ts = 0;
+				t0 = VTIM_mono();
+				pthread_mutex_unlock(&mtx);
+				break;
+			}
+			if (i != 1)
+				break;
+
 			/* get the value we want, and register if it's a hit*/
 			tag = VSL_TAG(tr->c->rec.ptr);
 
@@ -269,6 +314,8 @@ accumulate(struct VSL_data *vsl, struct VSL_transaction * const pt[],
 						"retry"))
 					skip = 1;
 				break;
+			case SLT_Timestamp:
+				tsp = VSL_CDATA(tr->c->rec.ptr);
 			default:
 				if (tag != match_tag)
 					break;
@@ -291,6 +338,12 @@ accumulate(struct VSL_data *vsl, struct VSL_transaction * const pt[],
 		if (skip || !match)
 			continue;
 
+		/*
+		 * only parse the last tsp seen in this transaction - it should
+		 * be the latest
+		 */
+		upd_vsl_ts(tsp);
+
 		/* select bucket */
 		i = HIST_RES * (log(value) / log_ten);
 		if (i < hist_low * HIST_RES)
@@ -300,6 +353,7 @@ accumulate(struct VSL_data *vsl, struct VSL_transaction * const pt[],
 		i -= hist_low * HIST_RES;
 		assert(i >= 0);
 		assert(i < hist_buckets);
+
 		pthread_mutex_lock(&mtx);
 
 		/* phase out old data */
@@ -331,6 +385,29 @@ accumulate(struct VSL_data *vsl, struct VSL_transaction * const pt[],
 		}
 		pthread_mutex_unlock(&mtx);
 	}
+
+	if (vsl_ts < vsl_to)
+		return (0);
+
+	t = VTIM_mono();
+
+	pthread_mutex_lock(&mtx);
+	if (vsl_t0 == 0)
+		vsl_to = vsl_t0 = vsl_ts;
+
+	assert(t > t0);
+	vsl_to = vsl_t0 + (t - t0) * timebend;
+
+	if (vsl_ts > vsl_to) {
+		double when = VTIM_real() + vsl_ts - vsl_to;
+		struct timespec ts;
+		// Lck_CondWait
+		ts.tv_nsec = (long)(modf(when, &t) * 1e9);
+		ts.tv_sec = (long)t;
+		(void) pthread_cond_timedwait(&timebend_cv, &mtx, &ts);
+	}
+	pthread_mutex_unlock(&mtx);
+
 	return (0);
 }
 
@@ -403,10 +480,28 @@ do_curses(void *arg)
 		case '-':
 			delay *= 2;
 			break;
+		case '>':
+		case '<':
+			// see below
+			break;
 		default:
 			beep();
 			break;
 		}
+
+		if (ch == '<' || ch == '>') {
+			pthread_mutex_lock(&mtx);
+			vsl_to = vsl_t0 = vsl_ts;
+			t0 = VTIM_mono();
+			if (timebend == 0)
+				timebend = 1;
+			else if (ch == '<')
+				timebend /= 2;
+			else
+				timebend *= 2;
+			pthread_cond_broadcast(&timebend_cv);
+			pthread_mutex_unlock(&mtx);
+		}
 	}
 	pthread_exit(NULL);
 }
@@ -445,8 +540,7 @@ main(int argc, char **argv)
 	cli_p.name = 0;
 
 	VUT_Init(progname);
-	if (0)
-		(void)usage;
+	AZ(pthread_cond_init(&timebend_cv, NULL));
 
 	while ((i = getopt(argc, argv, vopt_optstring)) != -1) {
 		switch (i) {
@@ -498,6 +592,23 @@ main(int argc, char **argv)
 			profile = NULL;
 			active_profile = &cli_p;
 
+			break;
+		case 'B':
+			timebend = strtod(optarg, NULL);
+			if (timebend == 0) {
+				fprintf(stderr,
+				    "-B: being able to bend time does not"
+				    " mean we can stop it"
+				    " (invalid factor '%s')\n", optarg);
+				exit(1);
+			}
+			if (timebend < 0) {
+				fprintf(stderr,
+				    "-B: being able to bend time does not"
+				    " mean we can make it go backwards"
+				    " (invalid factor '%s')\n", optarg);
+				exit(1);
+			}
 			break;
 		default:
 			if (!VUT_Arg(i, optarg))
@@ -535,6 +646,9 @@ main(int argc, char **argv)
 	bucket_hit = calloc(sizeof *bucket_hit, hist_buckets);
 	bucket_miss = calloc(sizeof *bucket_miss, hist_buckets);
 
+	if (timebend > 0)
+		t0 = VTIM_mono();
+
 	format = malloc(4 * fnum);
 	for (i = 0; i < fnum-1; i++) {
 		strcpy(format + 4*i, "%*s ");

bin/varnishhist/varnishhist_options.h

@@ -60,6 +60,16 @@
 	    " graph (these are power of ten)."				\
 	)
 
+#define HIS_OPT_B							\
+	VOPT("B:", "[-B <factor>]",					\
+	    "Time bending",						\
+	    "Factor to bend time by. Particularly usedful when"	\
+	    " [-r]eading from a vsl file. =1 process in near real"	\
+	    " time, <1 slow-motion, >1 time-lapse (useless unless"	\
+	    " reading from a file). At runtime, < halves and"		\
+	    " > doubles."						\
+	    )
+
 VSL_OPT_C
 VUT_OPT_d
 HIS_OPT_g
@@ -74,3 +84,4 @@ VUT_OPT_r
 VUT_OPT_t
 VSL_OPT_T
 VUT_OPT_V
+HIS_OPT_B