Quick-and-dirty test for timers code.

.gitignore

@@ -180,6 +180,7 @@ uptime-*.json
 /src/test/test-memwipe
 /src/test/test-ntor-cl
 /src/test/test-switch-id
+/src/test/test-timers
 /src/test/test_workqueue
 /src/test/test.exe
 /src/test/test-slow.exe
@@ -188,6 +189,7 @@ uptime-*.json
 /src/test/test-ntor-cl.exe
 /src/test/test-memwipe.exe
 /src/test/test-switch-id.exe
+/src/test/test-timers.exe
 /src/test/test_workqueue.exe
 /src/test/test_zero_length_keys.sh
 /src/test/test_ntor.sh

src/common/timers.c

@@ -79,12 +79,23 @@ static struct event *global_timer_event = NULL;
 /** We need to choose this value carefully.  Because we're using timer wheels,
  * it actually costs us to have extra resolution we don't use.  So for now,
  * I'm going to define our resolution as .1 msec, and hope that's good enough.
+ *
+ * Note that two of the most popular libevent backends (epoll without timerfd,
+ * and windows select), simply can't support sub-millisecond resolution,
+ * do this is optimistic for a lot of users.
  */
 #define USEC_PER_TICK 100
 
 /** One million microseconds in a second */
 #define USEC_PER_SEC 1000000
 
+/** Check at least once every N seconds. */
+#define MIN_CHECK_SECONDS 3600
+
+/** Check at least once every N ticks. */
+#define MIN_CHECK_TICKS \
+  (((timeout_t)MIN_CHECK_SECONDS) * (1000000 / USEC_PER_TICK))
+
 /**
  * Convert the timeval in <b>tv</b> to a timeout_t, and return it.
  *
@@ -135,8 +146,10 @@ libevent_timer_reschedule(void)
   tor_gettimeofday_cached_monotonic(&now);
   timer_advance_to_cur_time(&now);
 
-  const timeout_t delay = timeouts_timeout(global_timeouts);
+  timeout_t delay = timeouts_timeout(global_timeouts);
   struct timeval d;
+  if (delay > MIN_CHECK_TICKS)
+    delay = MIN_CHECK_TICKS;
   timeout_to_tv(delay, &d);
   event_add(global_timer_event, &d);
 }
@@ -153,6 +166,7 @@ libevent_timer_callback(evutil_socket_t fd, short what, void *arg)
   (void)arg;
 
   struct timeval now;
+  tor_gettimeofday_cache_clear();
   tor_gettimeofday_cached_monotonic(&now);
   timer_advance_to_cur_time(&now);
 
@@ -187,6 +201,8 @@ timers_initialize(void)
                               -1, 0, libevent_timer_callback, NULL);
   tor_assert(timer_event);
   global_timer_event = timer_event;
+
+  libevent_timer_reschedule();
 }
 
 /**
@@ -253,12 +269,15 @@ timer_schedule(tor_timer_t *t, const struct timeval *tv)
   tor_gettimeofday_cached_monotonic(&now);
   timer_advance_to_cur_time(&now);
 
+  /* Take the old timeout value. */
+  timeout_t to = timeouts_timeout(global_timeouts);
+
   timeouts_add(global_timeouts, t, when);
 
   /* Should we update the libevent timer? */
   if (to <= when) {
     return; /* we're already going to fire before this timer would trigger. */
-
+  }
   libevent_timer_reschedule();
 }
 

src/test/include.am

@@ -17,6 +17,7 @@ endif
 
 TESTS += src/test/test src/test/test-slow src/test/test-memwipe \
 	src/test/test_workqueue src/test/test_keygen.sh \
+	src/test/test-timers \
 	$(TESTSCRIPTS)
 
 # These flavors are run using automake's test-driver and test-network.sh
@@ -40,7 +41,8 @@ noinst_PROGRAMS+= \
 	src/test/test-memwipe \
 	src/test/test-child \
 	src/test/test_workqueue \
-	src/test/test-switch-id
+	src/test/test-switch-id \
+	src/test/test-timers
 endif
 
 src_test_AM_CPPFLAGS = -DSHARE_DATADIR="\"$(datadir)\"" \
@@ -127,6 +129,8 @@ src_test_test_slow_SOURCES = \
 src_test_test_memwipe_SOURCES = \
 	src/test/test-memwipe.c
 
+src_test_test_timers_SOURCES = \
+	src/test/test-timers.c
 
 src_test_test_CFLAGS = $(AM_CFLAGS) $(TEST_CFLAGS)
 
@@ -190,6 +194,16 @@ src_test_test_workqueue_LDADD = src/or/libtor-testing.a \
 	@TOR_ZLIB_LIBS@ @TOR_LIB_MATH@ @TOR_LIBEVENT_LIBS@ \
 	@TOR_OPENSSL_LIBS@ @TOR_LIB_WS32@ @TOR_LIB_GDI@ @CURVE25519_LIBS@
 
+src_test_test_timers_CPPFLAGS = $(src_test_test_CPPFLAGS)
+src_test_test_timers_CFLAGS = $(src_test_test_CFLAGS)
+src_test_test_timers_LDADD = \
+	src/common/libor-event-testing.a \
+	src/common/libor-crypto-testing.a $(LIBKECCAK_TINY) $(LIBDONNA) \
+	src/common/libor-testing.a \
+	@TOR_ZLIB_LIBS@ @TOR_LIB_MATH@ @TOR_LIBEVENT_LIBS@ \
+	@TOR_OPENSSL_LIBS@ @TOR_LIB_WS32@ @TOR_LIB_GDI@ @CURVE25519_LIBS@
+src_test_test_timers_LDFLAGS = $(src_test_test_LDFLAGS)
+
 noinst_HEADERS+= \
 	src/test/fakechans.h \
 	src/test/log_test_helpers.h \

src/test/test-timers.c

+/* Copyright 2016, The Tor Project, Inc. */
+/* See LICENSE for licensing information */
+
+#include "orconfig.h"
+
+#include <math.h>
+#include <stdio.h>
+#include <string.h>
+
+#ifdef HAVE_EVENT2_EVENT_H
+#include <event2/event.h>
+#else
+#include <event.h>
+#endif
+
+#include "compat.h"
+#include "compat_libevent.h"
+#include "crypto.h"
+#include "timers.h"
+#include "util.h"
+
+#define N_TIMERS 1000
+#define MAX_DURATION 30
+
+static struct timeval fire_at[N_TIMERS] = {{0,0}};
+static int fired[N_TIMERS] = {0};
+static struct timeval difference[N_TIMERS] = {{0,0}};
+static tor_timer_t *timers[N_TIMERS] = {NULL};
+
+static int n_fired = 0;
+
+static void
+timer_cb(tor_timer_t *t, void *arg, const struct timeval *now)
+{
+  tor_timer_t **t_ptr = arg;
+  tor_assert(*t_ptr == t);
+  int idx = (int) (t_ptr - timers);
+  ++fired[idx];
+  timersub(now, &fire_at[idx], &difference[idx]);
+  ++n_fired;
+  // printf("%d / %d\n",n_fired, N_TIMERS);
+  if (n_fired == N_TIMERS) {
+    event_base_loopbreak(tor_libevent_get_base());
+  }
+}
+
+int
+main(int argc, char **argv)
+{
+  (void)argc;
+  (void)argv;
+  tor_libevent_cfg cfg;
+  memset(&cfg, 0, sizeof(cfg));
+  tor_libevent_initialize(&cfg);
+  timers_initialize();
+
+  int i;
+  struct timeval now;
+  tor_gettimeofday(&now);
+  for (i = 0; i < N_TIMERS; ++i) {
+    struct timeval delay;
+    delay.tv_sec = crypto_rand_int_range(0,MAX_DURATION);
+    delay.tv_usec = crypto_rand_int_range(0,1000000);
+    timeradd(&now, &delay, &fire_at[i]);
+    timers[i] = timer_new(timer_cb, &timers[i], 0);
+    timer_schedule(timers[i], &delay);
+  }
+
+  event_base_loop(tor_libevent_get_base(), 0);
+
+  uint64_t total_difference = 0;
+  uint64_t total_square_difference = 0;
+  tor_assert(n_fired == N_TIMERS);
+  for (i = 0; i < N_TIMERS; ++i) {
+    tor_assert(fired[i] == 1);
+    uint64_t diff = difference[i].tv_usec + difference[i].tv_sec * 1000000;
+    total_difference += diff;
+    total_square_difference += diff*diff;
+  }
+  const uint64_t mean_diff = total_difference / N_TIMERS;
+  printf("mean difference: "U64_FORMAT" usec\n",
+         U64_PRINTF_ARG(mean_diff));
+
+  const double mean_sq = ((double)total_square_difference) / N_TIMERS;
+  const double sq_mean = mean_diff * mean_diff;
+  const double stddev = sqrt(mean_sq - sq_mean);
+  printf("standard deviation: %lf usec\n", stddev);
+
+  if (mean_diff > 500*1000 || stddev > 500*1000) {
+    printf("Either your system is under ridiculous load, or the "
+           "timer backend is broken.\n");
+    return 1;
+  } else if (mean_diff > 2000 || stddev > 2000) {
+    printf("Either your system is a bit slow or the "
+           "timer backend is odd.\n");
+    return 0;
+  } else {
+    printf("Looks good enough.\n");
+  }
+  return 0;
+}