From b460142451b144e3ff9157c5e15cbd6f2fe0312f Mon Sep 17 00:00:00 2001
From: Ben Noordhuis <info@bnoordhuis.nl>
Date: Thu, 12 Sep 2013 23:58:41 +0200
Subject: [PATCH] bench: measure total/init/dispatch/cleanup times

* Add finer-grained measurements to the million_timers benchmark.
  Before this commit it only measured the total running time.

* Bump the number of inserted timers from 1M to 10M.  With one million
  timers, it finishes too quickly to get useful profiling data out of
  it with perf or oprofile.  The name of the benchmark is now a lie but
  such is life.
---
 test/benchmark-million-timers.c | 20 ++++++++++++++------
 1 file changed, 14 insertions(+), 6 deletions(-)

diff --git a/test/benchmark-million-timers.c b/test/benchmark-million-timers.c
index fe887344..64f4a103 100644
--- a/test/benchmark-million-timers.c
+++ b/test/benchmark-million-timers.c
@@ -22,7 +22,7 @@
 #include "task.h"
 #include "uv.h"
 
-#define NUM_TIMERS (1000 * 1000)
+#define NUM_TIMERS (10 * 1000 * 1000)
 
 static int timer_cb_called;
 static int close_cb_called;
@@ -41,8 +41,10 @@ static void close_cb(uv_handle_t* handle) {
 BENCHMARK_IMPL(million_timers) {
   uv_timer_t* timers;
   uv_loop_t* loop;
-  uint64_t before;
-  uint64_t after;
+  uint64_t before_all;
+  uint64_t before_run;
+  uint64_t after_run;
+  uint64_t after_all;
   int timeout;
   int i;
 
@@ -52,25 +54,31 @@ BENCHMARK_IMPL(million_timers) {
   loop = uv_default_loop();
   timeout = 0;
 
+  before_all = uv_hrtime();
   for (i = 0; i < NUM_TIMERS; i++) {
     if (i % 1000 == 0) timeout++;
     ASSERT(0 == uv_timer_init(loop, timers + i));
     ASSERT(0 == uv_timer_start(timers + i, timer_cb, timeout, 0));
   }
 
-  before = uv_hrtime();
+  before_run = uv_hrtime();
   ASSERT(0 == uv_run(loop, UV_RUN_DEFAULT));
-  after = uv_hrtime();
+  after_run = uv_hrtime();
 
   for (i = 0; i < NUM_TIMERS; i++)
     uv_close((uv_handle_t*) (timers + i), close_cb);
 
   ASSERT(0 == uv_run(loop, UV_RUN_DEFAULT));
+  after_all = uv_hrtime();
+
   ASSERT(timer_cb_called == NUM_TIMERS);
   ASSERT(close_cb_called == NUM_TIMERS);
   free(timers);
 
-  LOGF("%.2f seconds\n", (after - before) / 1e9);
+  LOGF("%.2f seconds total\n", (after_all - before_all) / 1e9);
+  LOGF("%.2f seconds init\n", (before_run - before_all) / 1e9);
+  LOGF("%.2f seconds dispatch\n", (after_run - before_run) / 1e9);
+  LOGF("%.2f seconds cleanup\n", (after_all - after_run) / 1e9);
 
   MAKE_VALGRIND_HAPPY();
   return 0;