From b98a061c248a47fe1bafbe83494d362a90436cb8 Mon Sep 17 00:00:00 2001
From: Eelco Dolstra <eelco.dolstra@logicblox.com>
Date: Wed, 2 Mar 2016 14:18:39 +0100
Subject: [PATCH] Add some instrumentation to keep track of dispatcher cost

---
 src/hydra-queue-runner/builder.cc            | 2 ++
 src/hydra-queue-runner/dispatcher.cc         | 8 +++++++-
 src/hydra-queue-runner/hydra-queue-runner.cc | 3 +++
 src/hydra-queue-runner/state.hh              | 2 ++
 4 files changed, 14 insertions(+), 1 deletion(-)

diff --git a/src/hydra-queue-runner/builder.cc b/src/hydra-queue-runner/builder.cc
index 9179fe42..e8f06570 100644
--- a/src/hydra-queue-runner/builder.cc
+++ b/src/hydra-queue-runner/builder.cc
@@ -10,6 +10,8 @@ void State::builder(MachineReservation::ptr reservation)
 {
     bool retry = true;
 
+    nrStepsStarted++;
+
     MaintainCount mc(nrActiveSteps);
 
     auto step = reservation->step;
diff --git a/src/hydra-queue-runner/dispatcher.cc b/src/hydra-queue-runner/dispatcher.cc
index c50b79b5..b6134c21 100644
--- a/src/hydra-queue-runner/dispatcher.cc
+++ b/src/hydra-queue-runner/dispatcher.cc
@@ -32,9 +32,16 @@ void State::dispatcher()
 {
     while (true) {
         printMsg(lvlDebug, "dispatcher woken up");
+        nrDispatcherWakeups++;
+
+        auto now1 = std::chrono::steady_clock::now();
 
         auto sleepUntil = doDispatch();
 
+        auto now2 = std::chrono::steady_clock::now();
+
+        dispatchTimeMs += std::chrono::duration_cast<std::chrono::milliseconds>(now2 - now1).count();
+
         /* Sleep until we're woken up (either because a runnable build
            is added, or because a build finishes). */
         {
@@ -44,7 +51,6 @@ void State::dispatcher()
                     std::chrono::duration_cast<std::chrono::seconds>(sleepUntil - std::chrono::system_clock::now()).count());
                 dispatcherWakeup_.wait_until(dispatcherWakeupCV, sleepUntil);
             }
-            nrDispatcherWakeups++;
             *dispatcherWakeup_ = false;
         }
     }
diff --git a/src/hydra-queue-runner/hydra-queue-runner.cc b/src/hydra-queue-runner/hydra-queue-runner.cc
index d7e80f82..51070e18 100644
--- a/src/hydra-queue-runner/hydra-queue-runner.cc
+++ b/src/hydra-queue-runner/hydra-queue-runner.cc
@@ -550,6 +550,7 @@ void State::dumpStatus(Connection & conn, bool log)
         root.attr("bytesReceived", bytesReceived);
         root.attr("nrBuildsRead", nrBuildsRead);
         root.attr("nrBuildsDone", nrBuildsDone);
+        root.attr("nrStepsStarted", nrStepsStarted);
         root.attr("nrStepsDone", nrStepsDone);
         root.attr("nrRetries", nrRetries);
         root.attr("maxNrRetries", maxNrRetries);
@@ -561,6 +562,8 @@ void State::dumpStatus(Connection & conn, bool log)
         }
         root.attr("nrQueueWakeups", nrQueueWakeups);
         root.attr("nrDispatcherWakeups", nrDispatcherWakeups);
+        root.attr("dispatchTimeMs", dispatchTimeMs);
+        root.attr("dispatchTimeAvgMs", nrDispatcherWakeups == 0 ? 0.0 : (float) dispatchTimeMs / nrDispatcherWakeups);
         root.attr("nrDbConnections", dbPool.count());
         root.attr("nrActiveDbUpdates", nrActiveDbUpdates);
         {
diff --git a/src/hydra-queue-runner/state.hh b/src/hydra-queue-runner/state.hh
index 669bce3e..cc972d79 100644
--- a/src/hydra-queue-runner/state.hh
+++ b/src/hydra-queue-runner/state.hh
@@ -295,6 +295,7 @@ private:
     time_t startedAt;
     counter nrBuildsRead{0};
     counter nrBuildsDone{0};
+    counter nrStepsStarted{0};
     counter nrStepsDone{0};
     counter nrActiveSteps{0};
     counter nrStepsBuilding{0};
@@ -307,6 +308,7 @@ private:
     counter totalStepBuildTime{0}; // total build time for steps
     counter nrQueueWakeups{0};
     counter nrDispatcherWakeups{0};
+    counter dispatchTimeMs{0};
     counter bytesSent{0};
     counter bytesReceived{0};
     counter nrActiveDbUpdates{0};