Improve "waiting for locks" messages

edolstra · edolstra · commit 5ed5d7acbd00 · 2020-06-15T16:03:29.000+02:00
These are now shown in the progress bar. Closes #3577.
diff --git a/src/libmain/progress-bar.cc b/src/libmain/progress-bar.cc
@@ -156,7 +156,7 @@ class ProgressBar : public Logger
     {
         auto state(state_.lock());
 
-        if (lvl <= verbosity && !s.empty())
+        if (lvl <= verbosity && !s.empty() && type != actBuildWaiting)
             log(*state, lvl, s + "...");
 
         state->activities.emplace_back(ActInfo());
diff --git a/src/libstore/build.cc b/src/libstore/build.cc
@@ -869,6 +869,9 @@ class DerivationGoal : public Goal
 
     std::unique_ptr<Activity> act;
 
+    /* Activity that denotes waiting for a lock. */
+    std::unique_ptr<Activity> actLock;
+
     std::map<ActivityId, Activity> builderActivities;
 
     /* The remote machine on which we're building. */
@@ -1439,10 +1442,15 @@ void DerivationGoal::tryToBuild()
         lockFiles.insert(worker.store.Store::toRealPath(outPath));
 
     if (!outputLocks.lockPaths(lockFiles, "", false)) {
+        if (!actLock)
+            actLock = std::make_unique<Activity>(*logger, lvlWarn, actBuildWaiting,
+                fmt("waiting for lock on %s", yellowtxt(showPaths(lockFiles))));
         worker.waitForAWhile(shared_from_this());
         return;
     }
 
+    actLock.reset();
+
     /* Now check again whether the outputs are valid.  This is because
        another process may have started building in parallel.  After
        it has finished and released the locks, we can (and should)
@@ -1481,13 +1489,17 @@ void DerivationGoal::tryToBuild()
             case rpAccept:
                 /* Yes, it has started doing so.  Wait until we get
                    EOF from the hook. */
+                actLock.reset();
                 result.startTime = time(0); // inexact
                 state = &DerivationGoal::buildDone;
                 started();
                 return;
             case rpPostpone:
                 /* Not now; wait until at least one child finishes or
                    the wake-up timeout expires. */
+                if (!actLock)
+                    actLock = std::make_unique<Activity>(*logger, lvlWarn, actBuildWaiting,
+                        fmt("waiting for a machine to build '%s'", yellowtxt(worker.store.printStorePath(drvPath))));
                 worker.waitForAWhile(shared_from_this());
                 outputLocks.unlock();
                 return;
@@ -1497,6 +1509,8 @@ void DerivationGoal::tryToBuild()
         }
     }
 
+    actLock.reset();
+
     /* Make sure that we are allowed to start a build.  If this
        derivation prefers to be done locally, do it even if
        maxBuildJobs is 0. */
@@ -1524,7 +1538,9 @@ void DerivationGoal::tryLocalBuild() {
                uid. */
             buildUser->kill();
         } else {
-            debug("waiting for build users");
+            if (!actLock)
+                actLock = std::make_unique<Activity>(*logger, lvlWarn, actBuildWaiting,
+                    fmt("waiting for UID to build '%s'", yellowtxt(worker.store.printStorePath(drvPath))));
             worker.waitForAWhile(shared_from_this());
             return;
         }
@@ -1535,6 +1551,8 @@ void DerivationGoal::tryLocalBuild() {
 #endif
     }
 
+    actLock.reset();
+
     try {
 
         /* Okay, we have to build. */
@@ -4863,8 +4881,6 @@ void Worker::waitForInput()
        up after a few seconds at most. */
     if (!waitingForAWhile.empty()) {
         useTimeout = true;
-        if (lastWokenUp == steady_time_point::min())
-            printInfo("waiting for locks, build slots or build users...");
         if (lastWokenUp == steady_time_point::min() || lastWokenUp > before) lastWokenUp = before;
         timeout = std::max(1L,
             (long) std::chrono::duration_cast<std::chrono::seconds>(
diff --git a/src/libutil/logging.hh b/src/libutil/logging.hh
@@ -18,6 +18,7 @@ typedef enum {
     actSubstitute = 108,
     actQueryPathInfo = 109,
     actPostBuildHook = 110,
+    actBuildWaiting = 111,
 } ActivityType;
 
 typedef enum {

Original file line number	Diff line number	Diff line change
`@@ -156,7 +156,7 @@ class ProgressBar : public Logger`
`156`	`156`	`{`
`157`	`157`	`auto state(state_.lock());`
`158`	`158`
`159`		`- if (lvl <= verbosity && !s.empty())`
	`159`	`+ if (lvl <= verbosity && !s.empty() && type != actBuildWaiting)`
`160`	`160`	`log(*state, lvl, s + "...");`
`161`	`161`
`162`	`162`	`state->activities.emplace_back(ActInfo());`