IO loops now actually measuring their time (show threads all works)

2 files changed, 60 insertions, 2 deletions

diff --git a/sysdep/unix/io-loop.c b/sysdep/unix/io-loop.c
index 1a3333ef..db8556a6 100644
--- a/sysdep/unix/io-loop.c
+++ b/sysdep/unix/io-loop.c
@@ -49,15 +49,20 @@ static void ns_init(void)
     bug("clock_gettime: %m");
 }
 
+#define NSEC_IN_SEC	((u64) (1000 * 1000 * 1000))
+
 static u64 ns_now(void)
 {
   struct timespec ts;
   if (clock_gettime(CLOCK_MONOTONIC, &ts))
     bug("clock_gettime: %m");
 
-  return (u64) (ts.tv_sec - ns_begin.tv_sec) * 1000000000 + ts.tv_nsec - ns_begin.tv_nsec;
+  return (u64) (ts.tv_sec - ns_begin.tv_sec) * NSEC_IN_SEC + ts.tv_nsec - ns_begin.tv_nsec;
 }
 
+#define NSEC_TO_SEC(x)	((x) / NSEC_IN_SEC)
+#define CURRENT_SEC	NSEC_TO_SEC(ns_now())
+
 
 /*
  *	Current thread context
@@ -960,7 +965,21 @@ bird_thread_show(void *data)
   WALK_LIST(loop, this_thread->loops)
   {
     if (tsd->show_loops)
-      cli_printf(tsd->cli, -1026, "  Loop %s time: %t", domain_name(loop->time.domain), loop->total_time_spent_ns NS);
+    {
+      char b[TIME_BY_SEC_SIZE * sizeof("123456789, ")], *bptr = b, *bend = b + sizeof(b);
+      uint cs = CURRENT_SEC;
+      uint fs = NSEC_TO_SEC(loop->last_time_finished_ns);
+      for (uint i = 0; i <= cs && i < TIME_BY_SEC_SIZE; i++)
+	bptr += bsnprintf(bptr, bend - bptr, "% 9lu ",
+	    (cs - i > fs) ? 0 : loop->time_by_sec_ns[(cs - i) % TIME_BY_SEC_SIZE]);
+      bptr[-1] = 0; /* Drop the trailing space */
+
+      cli_printf(tsd->cli, -1026, "  Loop %s total time: %t",
+	  domain_name(loop->time.domain), loop->total_time_spent_ns NS);
+      cli_printf(tsd->cli, -1026, "    last %d secs [ns]: %s",
+	  MIN(CURRENT_SEC+1, TIME_BY_SEC_SIZE), b);
+    }
+
     total_time_ns += loop->total_time_spent_ns;
   }
 
@@ -1204,6 +1223,37 @@ birdloop_run(void *_loop)
   this_thread->sock_changed += loop->sock_changed;
   loop->sock_changed = 0;
 
+  /* Get finish time */
+  u64 finish_time = ns_now();
+  loop->total_time_spent_ns += finish_time - locked_time;
+
+  log(L_INFO "%p: lock to finish time: %lu %lu", loop, locked_time, finish_time);
+
+  /* Zero records for seconds where we haven't run */
+  if (NSEC_TO_SEC(loop->last_time_finished_ns) + TIME_BY_SEC_SIZE < NSEC_TO_SEC(locked_time))
+    memset(loop->time_by_sec_ns, 0, sizeof(loop->time_by_sec_ns));
+  else
+    for (u64 fclr = NSEC_TO_SEC(loop->last_time_finished_ns) + 1;
+	fclr <= NSEC_TO_SEC(locked_time);
+	fclr++)
+    {
+      log(L_INFO "%p: fclr %lu", loop, fclr % TIME_BY_SEC_SIZE);
+      loop->time_by_sec_ns[fclr % TIME_BY_SEC_SIZE] = 0;
+    }
+
+  while (NSEC_TO_SEC(locked_time) != NSEC_TO_SEC(finish_time))
+  {
+    u64 part = (NSEC_TO_SEC(locked_time) + 1) * NSEC_IN_SEC - locked_time;
+    log(L_INFO "%p: part %lu to %lu", loop, part, NSEC_TO_SEC(locked_time) % TIME_BY_SEC_SIZE);
+    loop->time_by_sec_ns[NSEC_TO_SEC(locked_time) % TIME_BY_SEC_SIZE] += part;
+    locked_time += part;
+  }
+
+  log(L_INFO "%p: part %lu to %lu", loop, finish_time - locked_time, NSEC_TO_SEC(locked_time) % TIME_BY_SEC_SIZE);
+  loop->time_by_sec_ns[NSEC_TO_SEC(locked_time) % TIME_BY_SEC_SIZE] += finish_time - locked_time;
+
+  loop->last_time_finished_ns = finish_time;
+
   birdloop_leave(loop);
 }
 
diff --git a/sysdep/unix/io-loop.h b/sysdep/unix/io-loop.h
index 2b0b7ebf..b5da7aba 100644
--- a/sysdep/unix/io-loop.h
+++ b/sysdep/unix/io-loop.h
@@ -29,6 +29,11 @@ void pipe_pollin(struct pipe *, struct pfd *);
 void pipe_drain(struct pipe *);
 void pipe_kick(struct pipe *);
 
+struct total_time_since {
+  u64 total;
+  u64 since;
+};
+
 struct birdloop
 {
   node n;
@@ -60,6 +65,9 @@ struct birdloop
 
   struct bird_thread *thread;
 
+#define TIME_BY_SEC_SIZE	16
+  u64 time_by_sec_ns[TIME_BY_SEC_SIZE];
+  u64 last_time_finished_ns;
   u64 total_time_spent_ns;
 };