Keep track of the time we spend copying to/from build machines

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

@@ -229,7 +229,14 @@ void State::buildRemote(ref<Store> store,
         mc1.reset();
         MaintainCount mc2(nrStepsCopyingTo);
         printMsg(lvlDebug, format("sending closure of ‘%1%’ to ‘%2%’") % step->drvPath % machine->sshName);
+
+        auto now1 = std::chrono::steady_clock::now();
+
         copyClosureTo(store, from, to, inputs, bytesSent);
+
+        auto now2 = std::chrono::steady_clock::now();
+
+        result.overhead += std::chrono::duration_cast<std::chrono::milliseconds>(now2 - now1).count();
     }
 
     autoDelete.cancel();
@@ -283,7 +290,14 @@ void State::buildRemote(ref<Store> store,
         for (auto & output : step->drv.outputs)
             outputs.insert(output.second.path);
         MaintainCount mc(nrStepsCopyingFrom);
+
+        auto now1 = std::chrono::steady_clock::now();
+
         copyClosureFrom(store, from, to, outputs, bytesReceived);
+
+        auto now2 = std::chrono::steady_clock::now();
+
+        result.overhead += std::chrono::duration_cast<std::chrono::milliseconds>(now2 - now1).count();
     }
 
     /* Shut down the connection. */

src/hydra-queue-runner/builder.cc

@@ -165,7 +165,7 @@ bool State::doBuildStep(nix::ref<Store> store, Step::ptr step,
         }
         if (retry) {
             pqxx::work txn(*conn);
-            finishBuildStep(txn, result.startTime, result.stopTime, build->id,
+            finishBuildStep(txn, result.startTime, result.stopTime, result.overhead, build->id,
                 stepNr, machine->sshName, bssAborted, result.errorMsg);
             txn.commit();
             if (quit) exit(1);
@@ -214,7 +214,8 @@ bool State::doBuildStep(nix::ref<Store> store, Step::ptr step,
             {
                 pqxx::work txn(*conn);
 
-                finishBuildStep(txn, result.startTime, result.stopTime, build->id, stepNr, machine->sshName, bssSuccess);
+                finishBuildStep(txn, result.startTime, result.stopTime, result.overhead,
+                    build->id, stepNr, machine->sshName, bssSuccess);
 
                 for (auto & b : direct)
                     markSucceededBuild(txn, b, res, build != b || result.status != BuildResult::Built,
@@ -334,8 +335,8 @@ bool State::doBuildStep(nix::ref<Store> store, Step::ptr step,
                 }
 
                 if (!cachedFailure)
-                    finishBuildStep(txn, result.startTime, result.stopTime, build->id,
-                        stepNr, machine->sshName, buildStepStatus, result.errorMsg);
+                    finishBuildStep(txn, result.startTime, result.stopTime, result.overhead,
+                        build->id, stepNr, machine->sshName, buildStepStatus, result.errorMsg);
 
                 /* Mark all builds that depend on this derivation as failed. */
                 for (auto & build2 : indirect) {

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

@@ -204,18 +204,20 @@ int State::createBuildStep(pqxx::work & txn, time_t startTime, Build::ptr build,
 }
 
 
-void State::finishBuildStep(pqxx::work & txn, time_t startTime, time_t stopTime, BuildID buildId, int stepNr,
-    const std::string & machine, BuildStepStatus status, const std::string & errorMsg, BuildID propagatedFrom)
+void State::finishBuildStep(pqxx::work & txn, time_t startTime, time_t stopTime, unsigned int overhead,
+    BuildID buildId, int stepNr, const std::string & machine, BuildStepStatus status,
+    const std::string & errorMsg, BuildID propagatedFrom)
 {
     assert(startTime);
     assert(stopTime);
     txn.parameterized
-        ("update BuildSteps set busy = 0, status = $1, propagatedFrom = $4, errorMsg = $5, startTime = $6, stopTime = $7, machine = $8 where build = $2 and stepnr = $3")
+        ("update BuildSteps set busy = 0, status = $1, propagatedFrom = $4, errorMsg = $5, startTime = $6, stopTime = $7, machine = $8, overhead = $9 where build = $2 and stepnr = $3")
         ((int) status)(buildId)(stepNr)
         (propagatedFrom, propagatedFrom != 0)
         (errorMsg, errorMsg != "")
         (startTime)(stopTime)
-        (machine, machine != "").exec();
+        (machine, machine != "")
+        (overhead, overhead != 0).exec();
 }
 
 

src/hydra-queue-runner/state.hh

@@ -49,6 +49,7 @@ typedef enum {
 struct RemoteResult : nix::BuildResult
 {
     time_t startTime = 0, stopTime = 0;
+    unsigned int overhead = 0;
     nix::Path logFile;
 
     bool canRetry()
@@ -363,7 +364,8 @@ private:
         const std::string & machine, BuildStepStatus status, const std::string & errorMsg = "",
         BuildID propagatedFrom = 0);
 
-    void finishBuildStep(pqxx::work & txn, time_t startTime, time_t stopTime, BuildID buildId, int stepNr,
+    void finishBuildStep(pqxx::work & txn, time_t startTime, time_t stopTime,
+        unsigned int overhead, BuildID buildId, int stepNr,
         const std::string & machine, BuildStepStatus status, const std::string & errorMsg = "",
         BuildID propagatedFrom = 0);
 

src/lib/Hydra/Schema/BuildSteps.pm

@@ -98,6 +98,11 @@ __PACKAGE__->table("BuildSteps");
   is_foreign_key: 1
   is_nullable: 1
 
+=head2 overhead
+
+  data_type: 'integer'
+  is_nullable: 1
+
 =cut
 
 __PACKAGE__->add_columns(
@@ -125,6 +130,8 @@ __PACKAGE__->add_columns(
   { data_type => "text", is_nullable => 1 },
   "propagatedfrom",
   { data_type => "integer", is_foreign_key => 1, is_nullable => 1 },
+  "overhead",
+  { data_type => "integer", is_nullable => 1 },
 );
 
 =head1 PRIMARY KEY
@@ -194,8 +201,8 @@ __PACKAGE__->belongs_to(
 );
 
 
-# Created by DBIx::Class::Schema::Loader v0.07033 @ 2015-02-25 16:27:20
-# DO NOT MODIFY THIS OR ANYTHING ABOVE! md5sum:ZbOxzCzFN7fIT9M2BFY0iQ
+# Created by DBIx::Class::Schema::Loader v0.07043 @ 2016-02-16 18:04:52
+# DO NOT MODIFY THIS OR ANYTHING ABOVE! md5sum:TRALbEoaF/OIOyERYCyxkw
 
 my %hint = (
     columns => [

src/sql/hydra.sql

@@ -273,6 +273,9 @@ create table BuildSteps (
 
     propagatedFrom integer,
 
+    -- Time in milliseconds spend copying stuff from/to build machines.
+    overhead      integer,
+
     primary key   (build, stepnr),
     foreign key   (build) references Builds(id) on delete cascade,
     foreign key   (propagatedFrom) references Builds(id) on delete cascade

src/sql/upgrade-45.sql

@@ -0,0 +1 @@
+alter table BuildSteps add column overhead integer;