Loop spent time refactored to separate structures and functions

2 files changed, 148 insertions, 87 deletions

diff --git a/sysdep/unix/io-loop.c b/sysdep/unix/io-loop.c
index b3d930cb..79cbe3fe 100644
--- a/sysdep/unix/io-loop.c
+++ b/sysdep/unix/io-loop.c
@@ -63,6 +63,80 @@ static u64 ns_now(void)
 #define NSEC_TO_SEC(x)	((x) / NSEC_IN_SEC)
 #define CURRENT_SEC	NSEC_TO_SEC(ns_now())
 
+static _Thread_local struct spent_time *account_target_spent_time;
+static _Thread_local u64 *account_target_total;
+static _Thread_local u64 account_last;
+
+static u64 account_finish(void)
+{
+  /* Get current time */
+  u64 now = ns_now();
+  u64 dif = now - account_last;
+
+  /* Update second by second */
+  if (account_target_spent_time)
+  {
+    /* Drop old time information if difference is too large */
+    if (NSEC_TO_SEC(account_last) + TIME_BY_SEC_SIZE - 1 < NSEC_TO_SEC(now))
+      account_last = (NSEC_TO_SEC(now) - TIME_BY_SEC_SIZE + 1) * NSEC_IN_SEC;
+
+    /* Zero new records */
+    if (NSEC_TO_SEC(account_target_spent_time->last_written_ns) + TIME_BY_SEC_SIZE < NSEC_TO_SEC(account_last))
+      memset(account_target_spent_time->by_sec_ns, 0, sizeof(account_target_spent_time->by_sec_ns));
+    else
+      for (u64 fclr = NSEC_TO_SEC(account_target_spent_time->last_written_ns) + 1;
+	  fclr <= NSEC_TO_SEC(now);
+	  fclr++)
+	account_target_spent_time->by_sec_ns[fclr % TIME_BY_SEC_SIZE] = 0;
+
+    /* Add times second by second */
+    while (NSEC_TO_SEC(account_last) != NSEC_TO_SEC(now))
+    {
+      u64 part = (NSEC_TO_SEC(account_last) + 1) * NSEC_IN_SEC - account_last;
+      account_target_spent_time->by_sec_ns[NSEC_TO_SEC(account_last) % TIME_BY_SEC_SIZE] += part;
+      account_last += part;
+    }
+
+    /* Update the last second */
+    account_target_spent_time->by_sec_ns[NSEC_TO_SEC(account_last) % TIME_BY_SEC_SIZE] += now - account_last;
+
+    /* Store the current time */
+    account_target_spent_time->last_written_ns = now;
+  }
+
+  /* Update the total */
+  if (account_target_total)
+    *account_target_total += dif;
+
+  /* Store current time */
+  account_last = now;
+
+  return dif;
+}
+
+static u64 account_to_spent_time(struct spent_time *st)
+{
+  u64 elapsed = account_finish();
+
+  account_target_spent_time = st;
+  account_target_total = &st->total_ns;
+
+  return elapsed;
+}
+
+static u64 account_to_total(u64 *total)
+{
+  u64 elapsed = account_finish();
+
+  account_target_spent_time = NULL;
+  account_target_total = total;
+
+  return elapsed;
+}
+
+#define account_to(_arg)	_Generic((_arg), \
+    struct spent_time *: account_to_spent_time, \
+    u64 *: account_to_total)(_arg)
 
 /*
  *	Current thread context
@@ -639,6 +713,8 @@ bird_thread_main(void *arg)
   rcu_thread_start(&thr->rcu);
   synchronize_rcu();
 
+  account_to(&thr->overhead);
+
   birdloop_enter(thr->meta);
 
   tmp_init(thr->pool, birdloop_domain(thr->meta));
@@ -952,6 +1028,29 @@ bird_thread_show_cli_cleanup(struct cli *c UNUSED)
 }
 
 static void
+bird_thread_show_spent_time(struct cli *c, const char *name, struct spent_time *st)
+{
+  char b[TIME_BY_SEC_SIZE * sizeof("1234567890, ")], *bptr = b, *bend = b + sizeof(b);
+  uint cs = CURRENT_SEC;
+  uint fs = NSEC_TO_SEC(st->last_written_ns);
+
+  for (uint i = 0; i <= cs && i < TIME_BY_SEC_SIZE; i++)
+    bptr += bsnprintf(bptr, bend - bptr, "% 10lu ",
+	(cs - i > fs) ? 0 : st->by_sec_ns[(cs - i) % TIME_BY_SEC_SIZE]);
+  bptr[-1] = 0; /* Drop the trailing space */
+
+  cli_printf(c, -1026, "    %s total time: % 9t s; last %d secs [ns]: %s", name, st->total_ns NS, MIN(CURRENT_SEC+1, TIME_BY_SEC_SIZE), b);
+}
+
+static void
+bird_thread_show_loop(struct cli *c, struct birdloop *loop)
+{
+  cli_printf(c, -1026, "  Loop %s", domain_name(loop->time.domain));
+  bird_thread_show_spent_time(c, "    Working", &loop->working);
+  bird_thread_show_spent_time(c, "    Locking", &loop->locking);
+}
+
+static void
 bird_thread_show(void *data)
 {
   struct bird_thread_show_data *tsd = data;
@@ -965,40 +1064,29 @@ bird_thread_show(void *data)
   WALK_LIST(loop, this_thread->loops)
   {
     if (tsd->show_loops)
-    {
-      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", domain_name(loop->time.domain));
-      cli_printf(tsd->cli, -1026, "    Total time: %t s", loop->total_time_spent_ns NS);
-      cli_printf(tsd->cli, -1026, "    Total locking time: %t s", loop->total_time_locking_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;
+      bird_thread_show_loop(tsd->cli, loop);
+    
+    total_time_ns += loop->working.total_ns + loop->locking.total_ns;
   }
 
-  tsd->done++;
-  int last = (tsd->done == tsd->total);
+  int last = (++tsd->done == tsd->total);
+
+  if (tsd->show_loops)
+  {
+    cli_printf(tsd->cli, (last ? 1 : -1) * 1026, "  Total working time: %t", total_time_ns NS);
+    bird_thread_show_spent_time(tsd->cli, "  Overhead", &this_thread->overhead);
+  }
+  else
+    cli_printf(tsd->cli, (last ? 1 : -1) * 1026, "Thread %p working %t s overhead %t s",
+	this_thread, total_time_ns NS, this_thread->overhead.total_ns NS);
 
   if (last)
   {
     tsd->cli->cont = NULL;
     tsd->cli->cleanup = NULL;
+    ev_send(&global_event_list, &tsd->finish_event);
   }
 
-  if (tsd->show_loops)
-    cli_printf(tsd->cli, (last ? 1 : -1) * 1026, "  Total time: %t", total_time_ns NS);
-  else
-    cli_printf(tsd->cli, (last ? 1 : -1) * 1026, "Thread %p time %t", this_thread, total_time_ns NS);
-
-  ev_send(&global_event_list, &tsd->finish_event);
-
   UNLOCK_DOMAIN(control, tsd->lock);
 }
 
@@ -1012,27 +1100,31 @@ bird_thread_show_finish(void *data)
       struct birdloop_pickup_group *group = &pickup_groups[i];
 
       LOCK_DOMAIN(resource, group->domain);
+      uint count = 0;
+      u64 total_time_ns = 0;
       if (!EMPTY_LIST(group->loops))
+      {
 	if (tsd->show_loops)
+	  cli_printf(tsd->cli, -1026, "Unassigned loops:");
+
+	struct birdloop *loop;
+	WALK_LIST(loop, group->loops)
 	{
-	  cli_printf(tsd->cli, -1026, "Unassigned loops");
+	  if (tsd->show_loops)
+	    bird_thread_show_loop(tsd->cli, loop);
 
-	  struct birdloop *loop;
-	  WALK_LIST(loop, group->loops)
-	    cli_printf(tsd->cli, -1026, "  Loop %s time: %t", domain_name(loop->time.domain), loop->total_time_spent_ns NS);
+	  total_time_ns += loop->working.total_ns + loop->locking.total_ns;
+	  count++;
 	}
+
+	if (tsd->show_loops)
+	  cli_printf(tsd->cli, 1026, "  Total working time: %t", total_time_ns NS);
 	else
-	{
-	  uint count = 0;
-	  u64 total_time_ns = 0;
-	  struct birdloop *loop;
-	  WALK_LIST(loop, group->loops)
-	  {
-	    count++;
-	    total_time_ns += loop->total_time_spent_ns;
-	  }
-	  cli_printf(tsd->cli, -1026, "Unassigned loops: %d, total time %t", count, total_time_ns NS);
-	}
+	  cli_printf(tsd->cli, 1026, "Unassigned %d loops, total time %t", count, total_time_ns NS);
+      }
+      else
+	cli_printf(tsd->cli, 1026, "All loops are assigned.");
+
       UNLOCK_DOMAIN(resource, group->domain);
     }
 
@@ -1156,6 +1248,7 @@ birdloop_stop_internal(struct birdloop *loop)
   /* Leave the loop context without causing any other fuss */
   ASSERT_DIE(!ev_active(&loop->event));
   loop->ping_pending = 0;
+  account_to(&this_thread->overhead);
   birdloop_leave(loop);
 
   /* Request local socket reload */
@@ -1173,17 +1266,13 @@ birdloop_run(void *_loop)
   /* Run priority events before the loop is executed */
   ev_run_list(&this_thread->priority_events);
 
-  u64 start_time = ns_now();
-  u64 end_time = start_time + this_thread->max_loop_time_ns;
-
   struct birdloop *loop = _loop;
+  account_to(&loop->locking);
   birdloop_enter(loop);
+  u64 dif = account_to(&loop->working);
 
-  u64 locked_time = ns_now(), task_done_time;
-  if (locked_time > end_time)
-    LOOP_WARN(loop, "locked %luns after its scheduled end time", locked_time - end_time);
-
-  loop->total_time_locking_ns += (locked_time - start_time);
+  if (dif > this_thread->max_loop_time_ns)
+    LOOP_WARN(loop, "locked %lu ns after its scheduled end time", dif);
 
   uint repeat, loop_runs = 0;
   do {
@@ -1208,7 +1297,7 @@ birdloop_run(void *_loop)
     repeat += ev_run_list(&loop->event_list);
 
     /* Check end time */
-  } while (((task_done_time = ns_now()) < end_time) && repeat);
+  } while (repeat && (ns_now() < account_last + this_thread->max_loop_time_ns));
 
   /* Request meta timer */
   timer *t = timers_first(&loop->time);
@@ -1225,37 +1314,7 @@ 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;
-
+  account_to(&this_thread->overhead);
   birdloop_leave(loop);
 }
 
diff --git a/sysdep/unix/io-loop.h b/sysdep/unix/io-loop.h
index d60b5206..9b0efb6c 100644
--- a/sysdep/unix/io-loop.h
+++ b/sysdep/unix/io-loop.h
@@ -29,9 +29,12 @@ 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;
+#define TIME_BY_SEC_SIZE	16
+
+struct spent_time {
+  u64 total_ns;
+  u64 last_written_ns;
+  u64 by_sec_ns[TIME_BY_SEC_SIZE];
 };
 
 struct birdloop
@@ -66,10 +69,7 @@ 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;
-  u64 total_time_locking_ns;
+  struct spent_time working, locking;
 };
 
 struct bird_thread
@@ -98,6 +98,8 @@ struct bird_thread
 
   u64 max_latency_ns;
   u64 max_loop_time_ns;
+
+  struct spent_time overhead;
 };
 
 #endif