Keep track of wait time per system type

I.e., how much time the currently runnable steps per system type have
been waiting. This is useful for deciding whether to provision more
machines.

src/hydra-queue-runner/dispatcher.cc

@@ -16,6 +16,7 @@ void State::makeRunnable(Step::ptr step)
         assert(step_->created);
         assert(!step->finished);
         assert(step_->deps.empty());
+        step_->runnableSince = std::chrono::system_clock::now();
     }
 
     {
@@ -143,7 +144,12 @@ system_time State::doDispatch()
            FIXME: O(n lg n); obviously, it would be better to keep a
            runnable queue sorted by priority. */
         std::vector<Step::ptr> runnableSorted;
-        std::unordered_map<std::string, unsigned int> runnablePerType;
+        struct RunnablePerType
+        {
+            unsigned int count{0};
+            std::chrono::seconds waitTime{0};
+        };
+        std::unordered_map<std::string, RunnablePerType> runnablePerType;
         {
             auto runnable_(runnable.lock());
             runnableSorted.reserve(runnable_->size());
@@ -158,12 +164,14 @@ system_time State::doDispatch()
 
                 ++i;
 
-                runnablePerType[step->systemType]++;
+                auto & r = runnablePerType[step->systemType];
+                r.count++;
 
                 /* Skip previously failed steps that aren't ready
                    to be retried. */
                 {
                     auto step_(step->state.lock());
+                    r.waitTime += std::chrono::duration_cast<std::chrono::seconds>(now - step_->runnableSince);
                     if (step_->tries > 0 && step_->after > now) {
                         if (step_->after < sleepUntil)
                             sleepUntil = step_->after;
@@ -219,8 +227,9 @@ system_time State::doDispatch()
                             break;
                         } else ++i;
                     assert(removed);
-                    assert(runnablePerType[step->systemType]);
-                    runnablePerType[step->systemType]--;
+                    auto & r = runnablePerType[step->systemType];
+                    assert(r.count);
+                    r.count--;
                 }
 
                 /* Make a slot reservation and start a thread to
@@ -243,9 +252,14 @@ system_time State::doDispatch()
             for (auto & i : *machineTypes_)
                 i.second.runnable = 0;
 
-            for (auto & i : runnablePerType)
-                (*machineTypes_)[i.first].runnable = i.second;
+            for (auto & i : runnablePerType) {
+                auto & j = (*machineTypes_)[i.first];
+                j.runnable = i.second.count;
+                j.waitTime = i.second.waitTime;
             }
+        }
+
+        lastDispatcherCheck = std::chrono::system_clock::to_time_t(now);
 
     } while (keepGoing);
 
@@ -309,6 +323,6 @@ State::MachineReservation::~MachineReservation()
         assert(machineType.running);
         machineType.running--;
         if (machineType.running == 0)
-            machineType.lastActive = time(0);
+            machineType.lastActive = std::chrono::system_clock::now();
     }
 }

src/hydra-queue-runner/hydra-queue-runner.cc

@@ -484,8 +484,11 @@ void State::dumpStatus(Connection & conn, bool log)
                 JSONObject nested2(out);
                 nested2.attr("runnable", i.second.runnable);
                 nested2.attr("running", i.second.running);
+                if (i.second.runnable > 0)
+                    nested2.attr("waitTime", i.second.waitTime.count() +
+                        i.second.runnable * (time(0) - lastDispatcherCheck));
                 if (i.second.running == 0)
-                    nested2.attr("lastActive", i.second.lastActive);
+                    nested2.attr("lastActive", std::chrono::system_clock::to_time_t(i.second.lastActive));
             }
         }
     }

src/hydra-queue-runner/state.hh

@@ -175,6 +175,9 @@ struct Step
 
         /* The lowest ID of any build depending on this step. */
         BuildID lowestBuildID{std::numeric_limits<BuildID>::max()};
+
+        /* The time at which this step became runnable. */
+        system_time runnableSince;
     };
 
     std::atomic_bool finished{false}; // debugging
@@ -324,7 +327,8 @@ private:
     struct MachineType
     {
         unsigned int runnable{0}, running{0};
-        time_t lastActive{0};
+        system_time lastActive;
+        std::chrono::seconds waitTime; // time runnable steps have been waiting
     };
 
     Sync<std::map<std::string, MachineType>> machineTypes;
@@ -339,6 +343,8 @@ private:
         ~MachineReservation();
     };
 
+    std::atomic<time_t> lastDispatcherCheck{0};
+
 public:
     State();