Log build/substitution finishes

src/libstore/build/derivation-goal.cc

@@ -650,6 +650,7 @@ void DerivationGoal::tryToBuild()
                    EOF from the hook. */
                 actLock.reset();
                 result.startTime = time(0); // inexact
+                startTime = std::chrono::steady_clock::now();
                 state = &DerivationGoal::buildDone;
                 started();
                 return;
@@ -997,6 +998,16 @@ void DerivationGoal::buildDone()
     }
 
     done(BuildResult::Built);
+
+    auto stopTime = std::chrono::steady_clock::now();
+
+    auto duration = std::chrono::duration_cast<std::chrono::milliseconds>(stopTime - startTime).count() / 1000.0;
+
+    // FIXME: associate with activity 'act'.
+    notice(ANSI_BOLD ANSI_GREEN "Built" ANSI_NORMAL " '%s' in %s%.1f s" ANSI_NORMAL ".",
+        worker.store.printStorePath(drvPath),
+        duration > 0.5 ? ANSI_BOLD : ANSI_NORMAL,
+        duration);
 }
 
 void DerivationGoal::resolvedFinished() {
@@ -1573,6 +1584,7 @@ void DerivationGoal::startBuilder()
         throw SysError("putting pseudoterminal into raw mode");
 
     result.startTime = time(0);
+    startTime = std::chrono::steady_clock::now();
 
     /* Fork a child to build the package. */
     ProcessOptions options;

src/libstore/build/derivation-goal.hh

@@ -194,6 +194,11 @@ struct DerivationGoal : public Goal
 
     BuildResult result;
 
+    /* Time the build started. 'result' also has a 'startTime' field,
+       but that's wall clock time, so we can't use it to compute the
+       build duration... */
+    std::chrono::time_point<std::chrono::steady_clock> startTime;
+
     /* The current round, if we're building multiple times. */
     size_t curRound = 1;
 

src/libstore/build/substitution-goal.cc

@@ -205,6 +205,8 @@ void SubstitutionGoal::tryToRun()
 
     outPipe.create();
 
+    startTime = std::chrono::steady_clock::now();
+
     promise = std::promise<void>();
 
     thr = std::thread([this]() {
@@ -280,6 +282,16 @@ void SubstitutionGoal::finished()
     worker.updateProgress();
 
     amDone(ecSuccess);
+
+    auto stopTime = std::chrono::steady_clock::now();
+
+    auto duration = std::chrono::duration_cast<std::chrono::milliseconds>(stopTime - startTime).count() / 1000.0;
+
+    // FIXME: associate with activity 'act'.
+    notice(ANSI_BOLD ANSI_GREEN "Substituted" ANSI_NORMAL " '%s' in %s%.1f s" ANSI_NORMAL ".",
+        worker.store.printStorePath(storePath),
+        duration > 0.5 ? ANSI_BOLD : ANSI_NORMAL,
+        duration);
 }
 
 

src/libstore/build/substitution-goal.hh

@@ -53,6 +53,9 @@ struct SubstitutionGoal : public Goal
     /* Content address for recomputing store path */
     std::optional<ContentAddress> ca;
 
+    /* Time substitution started. */
+    std::chrono::time_point<std::chrono::steady_clock> startTime;
+
     SubstitutionGoal(const StorePath & storePath, Worker & worker, RepairFlag repair = NoRepair, std::optional<ContentAddress> ca = std::nullopt);
     ~SubstitutionGoal();