From 101b15663bbd8974e784ce560afc2859e99c8077 Mon Sep 17 00:00:00 2001
From: Eelco Dolstra <edolstra@gmail.com>
Date: Fri, 27 Nov 2020 11:31:44 +0100
Subject: [PATCH] Log build/substitution finishes

---
 src/libstore/build/derivation-goal.cc   | 12 ++++++++++++
 src/libstore/build/derivation-goal.hh   |  5 +++++
 src/libstore/build/substitution-goal.cc | 12 ++++++++++++
 src/libstore/build/substitution-goal.hh |  3 +++
 4 files changed, 32 insertions(+)

diff --git a/src/libstore/build/derivation-goal.cc b/src/libstore/build/derivation-goal.cc
index 47d11dc53..83a31a272 100644
--- a/src/libstore/build/derivation-goal.cc
+++ b/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;
diff --git a/src/libstore/build/derivation-goal.hh b/src/libstore/build/derivation-goal.hh
index 8ee0be9e1..8d5cac3e5 100644
--- a/src/libstore/build/derivation-goal.hh
+++ b/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;
 
diff --git a/src/libstore/build/substitution-goal.cc b/src/libstore/build/substitution-goal.cc
index d16584f65..5cff803b8 100644
--- a/src/libstore/build/substitution-goal.cc
+++ b/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);
 }
 
 
diff --git a/src/libstore/build/substitution-goal.hh b/src/libstore/build/substitution-goal.hh
index dee2cecbf..7d5c1d058 100644
--- a/src/libstore/build/substitution-goal.hh
+++ b/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();