Timing event loop precisely

src/evt_core.c

@@ -172,17 +172,89 @@ void evt_core_free(struct evt_core_ctx* ctx) {
   g_hash_table_destroy (ctx->urltofd);
 }
 
+enum timing_config {
+  TIMING_ACTIVATED = 1 << 0,
+  TIMING_DISPLAY_START = 1 << 1,
+  TIMING_DISPLAY_END = 1 << 2,
+  TIMING_DISPLAY_BOTH = 1 << 3
+};
+
+struct timing_fx {
+  struct timespec start;
+  enum timing_config config;
+  uint8_t activated_start;
+  char start_template[255], end_template[255];
+};
+
+void timing_fx_init(struct timing_fx* tfx, enum timing_config conf, char* startt, char* endt) {
+  tfx->config = conf;
+  strncpy (tfx->start_template, startt, sizeof(tfx->start_template) - 1);
+  strncpy (tfx->end_template, endt, sizeof(tfx->end_template) - 1);
+  tfx->start_template[sizeof(tfx->start_template) - 1] = 0; // Enforce null terminated string
+  tfx->end_template[sizeof(tfx->end_template) - 1] = 0;
+}
+
+void timing_fx_start(struct timing_fx* tfx, ...) {
+  va_list args;
+  if (!(tfx->config & TIMING_ACTIVATED)) return;
+  if (tfx->config & (TIMING_DISPLAY_START | TIMING_DISPLAY_BOTH)) {
+    va_start(args, tfx);
+    vfprintf(stderr, tfx->start_template, args);
+    va_end(args);
+  }
+
+  if (clock_gettime(CLOCK_REALTIME, &tfx->start) == -1) {
+    perror("clock_gettime");
+    exit(EXIT_FAILURE);
+  }
+}
+
+double timing_fx_stop(struct timing_fx* tfx, ...) {
+  va_list args;
+  struct timespec stop;
+  double elapsed_in_cb;
+
+  if (!(tfx->config & TIMING_ACTIVATED)) return 0.;
+
+  if (clock_gettime(CLOCK_REALTIME, &stop) == -1) {
+    perror("clock_gettime");
+    exit(EXIT_FAILURE);
+  }
+
+  elapsed_in_cb = (double)elapsed_micros (&tfx->start, &stop) / 1000000.;
+
+  if (tfx->config & (TIMING_DISPLAY_END | TIMING_DISPLAY_BOTH)) {
+    va_start(args, tfx);
+    vfprintf(stderr, tfx->end_template, args);
+    fprintf(stderr, ": done in %f sec\n", elapsed_in_cb);
+    va_end(args);
+  }
+  return elapsed_in_cb;
+}
+
 void evt_core_loop(struct evt_core_ctx* ctx) {
   struct epoll_event current_event, events[EVT_CORE_MAX_EVENTS];
   struct evt_core_fdinfo* fdinfo;
   struct evt_core_cat* cat;
-  clock_t start, end;
+  int return_code;
+  clock_t start_timing, end_timing;
   double elapsed_in_cb;
+  struct timing_fx tfx_epoll, tfx_err, tfx_cb, tfx_loop;
+
+  enum timing_config base = ctx->verbose ? TIMING_ACTIVATED : 0;
+  timing_fx_init (&tfx_epoll, base | TIMING_DISPLAY_END, "", "[SLEPT]()");
+  timing_fx_init (&tfx_cb, base | TIMING_DISPLAY_BOTH, "[BEGIN CB](name=%s, url=%s, fd=%d)\n", "[END CB]()");
+  timing_fx_init (&tfx_err, base | TIMING_DISPLAY_BOTH, "[BEGIN ERR](name=%s, url=%s, fd=%d)\n", "[END ERR]()");
+  timing_fx_init (&tfx_loop, base | TIMING_DISPLAY_END, "", "[LOOP]()");
 
   printf("--- Start main loop\n");
   int num_fd, n = 0;
   while(1) {
+    timing_fx_start(&tfx_epoll);
     num_fd = epoll_wait(ctx->epollfd, events, EVT_CORE_MAX_EVENTS, -1);
+    timing_fx_stop(&tfx_epoll);
+
+    timing_fx_start(&tfx_loop);
     if (num_fd == -1) {
       perror("Failed to epoll_wait");
       exit(EXIT_FAILURE);
@@ -213,7 +285,12 @@ void evt_core_loop(struct evt_core_ctx* ctx) {
         fdinfo = evt_core_get_from_fd(ctx, err_fd);
         if (fdinfo != NULL) {
           if (fdinfo->cat->err_cb != NULL) {
-            if (fdinfo->cat->err_cb(ctx, fdinfo) == 1) {
+
+            timing_fx_start (&tfx_err, fdinfo->cat->name, fdinfo->url, fdinfo->fd);
+            return_code = fdinfo->cat->err_cb(ctx, fdinfo);
+            timing_fx_stop(&tfx_err);
+
+            if (return_code == 1) {
               fprintf(stderr, "Error on fd=%d on cat=%s is handled by app, not clearing it\n", err_fd, fdinfo->cat->name);
               continue;
             }
@@ -233,17 +310,13 @@ void evt_core_loop(struct evt_core_ctx* ctx) {
         fprintf(stderr, "Ignoring file descriptor %d as it is not registered. This is a bug.\n", events[n].data.fd);
         continue;
       }
-      if (ctx->verbose) {
+
-        fprintf(stderr, "[BEGIN CB](name=%s, url=%s, fd=%d)\n", fdinfo->cat->name, fdinfo->url, fdinfo->fd);
+      timing_fx_start(&tfx_cb, fdinfo->cat->name, fdinfo->url, fdinfo->fd);
-        start = clock();
-      }
       while(fdinfo->cat->cb(ctx, fdinfo) == 0);
-      if (ctx->verbose) {
+      timing_fx_stop(&tfx_cb);
-        end = clock();
-        elapsed_in_cb = ((double) (end - start)) / CLOCKS_PER_SEC;
-        fprintf(stderr, "[END CB](time=%f sec)\n",  elapsed_in_cb);
-      }
     }
+
+    timing_fx_stop(&tfx_loop);
   }
 
   evt_core_free(ctx);

src/evt_core.h

@@ -8,6 +8,7 @@
 #include <glib-2.0/gmodule.h>
 #include <glib-2.0/glib-object.h>
 #include "net_tools.h"
+#include "utils.h"
 
 #define EVT_CORE_MAX_EVENTS 10
 

src/meas_lat.c

@@ -7,6 +7,7 @@
 #include "evt_core.h"
 #include "net_tools.h"
 #include "socks5.h"
+#include "utils.h"
 
 struct measlat_ctx {
   int count, size, interval, verbose;
@@ -55,7 +56,6 @@ int on_udp_err(struct evt_core_ctx* ctx, struct evt_core_fdinfo* fdinfo) {
 
 int on_udp(struct evt_core_ctx* ctx, struct evt_core_fdinfo* fdinfo) {
   ssize_t res;
-  int secs, nsecs;
   uint64_t micro_sec;
   struct timespec curr;
   struct measure_conf* mc = fdinfo->other;
@@ -71,9 +71,7 @@ int on_udp(struct evt_core_ctx* ctx, struct evt_core_fdinfo* fdinfo) {
     exit(EXIT_FAILURE);
   }
 
-  secs = curr.tv_sec - head->emit_time.tv_sec;
+  micro_sec = elapsed_micros (&head->emit_time, &curr);
-  nsecs = curr.tv_nsec - head->emit_time.tv_nsec;
-  micro_sec = secs * 1000000 + nsecs / 1000;
   printf("Packet %llu latency %luµs\n", (unsigned long long)head->counter, micro_sec);
 
   if (head->counter >= mc->max_measure) {

src/utils.c

@@ -80,3 +80,15 @@ int ring_le(uint16_t v1, uint16_t v2) {
 int ring_lt(uint16_t v1, uint16_t v2) {
   return ring_gt(v2, v1);
 }
+
+uint64_t elapsed_micros(struct timespec* t1, struct timespec* t2) {
+  int secs, nsecs;
+  uint64_t micro_sec;
+
+  secs = t2->tv_sec - t1->tv_sec;
+  nsecs = t2->tv_nsec - t1->tv_nsec;
+  micro_sec = secs * 1000000 + nsecs / 1000;
+
+  return micro_sec;
+}
+

src/utils.h

@@ -23,3 +23,5 @@ int ring_gt(uint16_t v1, uint16_t v2);
 int ring_ge(uint16_t v1, uint16_t v2);
 int ring_lt(uint16_t v1, uint16_t v2);
 int ring_le(uint16_t v1, uint16_t v2);
+
+uint64_t elapsed_micros(struct timespec* t1, struct timespec* t2);