Add some instrumentation to keep track of dispatcher cost

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;

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;
         }
     }

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);
         {

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};