Progress indicator: More improvements

src/libstore/build.cc

@@ -122,8 +122,6 @@ protected:
     /* Whether the goal is finished. */
     ExitCode exitCode;
 
-    Activity act;
-
     Goal(Worker & worker) : worker(worker)
     {
         nrFailed = nrNoSubstituters = nrIncompleteClosure = 0;
@@ -246,6 +244,7 @@ private:
 public:
 
     const Activity act;
+    const Activity actDerivations;
     const Activity actSubstitutions;
 
     /* Set if at least one derivation had a BuildError (i.e. permanent
@@ -259,8 +258,14 @@ public:
 
     std::unique_ptr<HookInstance> hook;
 
+    uint64_t expectedBuilds = 0;
+    uint64_t doneBuilds = 0;
+    uint64_t failedBuilds = 0;
+    uint64_t runningBuilds = 0;
+
     uint64_t expectedSubstitutions = 0;
     uint64_t doneSubstitutions = 0;
+    uint64_t failedSubstitutions = 0;
     uint64_t runningSubstitutions = 0;
     uint64_t expectedDownloadSize = 0;
     uint64_t doneDownloadSize = 0;
@@ -328,7 +333,8 @@ public:
 
     void updateProgress()
     {
-        actSubstitutions.progress(doneSubstitutions, expectedSubstitutions + doneSubstitutions, runningSubstitutions);
+        actDerivations.progress(doneBuilds, expectedBuilds + doneBuilds, runningBuilds, failedBuilds);
+        actSubstitutions.progress(doneSubstitutions, expectedSubstitutions + doneSubstitutions, runningSubstitutions, failedSubstitutions);
         logger->event(evSetExpected, act, actDownload, expectedDownloadSize + doneDownloadSize);
         logger->event(evSetExpected, act, actCopyPath, expectedNarSize + doneNarSize);
     }
@@ -829,6 +835,10 @@ private:
 
     const static Path homeDir;
 
+    std::unique_ptr<MaintainCount<uint64_t>> mcExpectedBuilds, mcRunningBuilds;
+
+    std::unique_ptr<Activity> act;
+
 public:
     DerivationGoal(const Path & drvPath, const StringSet & wantedOutputs,
         Worker & worker, BuildMode buildMode = bmNormal);
@@ -926,7 +936,6 @@ private:
 
     void amDone(ExitCode result) override
     {
-        logger->event(evBuildFinished, act, result == ecSuccess);
         Goal::amDone(result);
     }
 
@@ -949,7 +958,8 @@ DerivationGoal::DerivationGoal(const Path & drvPath, const StringSet & wantedOut
     name = (format("building of '%1%'") % drvPath).str();
     trace("created");
 
-    logger->event(evBuildCreated, act, drvPath);
+    mcExpectedBuilds = std::make_unique<MaintainCount<uint64_t>>(worker.expectedBuilds);
+    worker.updateProgress();
 }
 
 
@@ -965,7 +975,8 @@ DerivationGoal::DerivationGoal(const Path & drvPath, const BasicDerivation & drv
     name = (format("building of %1%") % showPaths(drv.outputPaths())).str();
     trace("created");
 
-    logger->event(evBuildCreated, act, drvPath);
+    mcExpectedBuilds = std::make_unique<MaintainCount<uint64_t>>(worker.expectedBuilds);
+    worker.updateProgress();
 
     /* Prevent the .chroot directory from being
        garbage-collected. (See isActiveTempFile() in gc.cc.) */
@@ -1374,6 +1385,12 @@ void DerivationGoal::tryToBuild()
        supported for local builds. */
     bool buildLocally = buildMode != bmNormal || drv->willBuildLocally();
 
+    auto started = [&]() {
+        act = std::make_unique<Activity>(actBuild, fmt("building '%s'", drvPath));
+        mcRunningBuilds = std::make_unique<MaintainCount<uint64_t>>(worker.runningBuilds);
+        worker.updateProgress();
+    };
+
     /* Is the build hook willing to accept this job? */
     if (!buildLocally) {
         switch (tryBuildHook()) {
@@ -1382,6 +1399,7 @@ void DerivationGoal::tryToBuild()
                    EOF from the hook. */
                 result.startTime = time(0); // inexact
                 state = &DerivationGoal::buildDone;
+                started();
                 return;
             case rpPostpone:
                 /* Not now; wait until at least one child finishes or
@@ -1422,6 +1440,8 @@ void DerivationGoal::tryToBuild()
     /* This state will be reached when we get EOF on the child's
        log pipe. */
     state = &DerivationGoal::buildDone;
+
+    started();
 }
 
 
@@ -2147,8 +2167,6 @@ void DerivationGoal::startBuilder()
         }
         debug(msg);
     }
-
-    logger->event(evBuildStarted, act);
 }
 
 
@@ -3239,7 +3257,7 @@ void DerivationGoal::flushLine()
         logTail.push_back(currentLogLine);
         if (logTail.size() > settings.logLines) logTail.pop_front();
     }
-    logger->event(evBuildOutput, act, currentLogLine);
+    logger->event(evBuildOutput, *act, currentLogLine);
     currentLogLine = "";
     currentLogLinePos = 0;
 }
@@ -3282,6 +3300,19 @@ void DerivationGoal::done(BuildResult::Status status, const string & msg)
         worker.timedOut = true;
     if (result.status == BuildResult::PermanentFailure)
         worker.permanentFailure = true;
+
+    mcExpectedBuilds.reset();
+    mcRunningBuilds.reset();
+
+    if (result.success()) {
+        if (status == BuildResult::Built)
+            worker.doneBuilds++;
+    } else {
+        if (status != BuildResult::DependencyFailed)
+            worker.failedBuilds++;
+    }
+
+    worker.updateProgress();
 }
 
 
@@ -3432,6 +3463,12 @@ void SubstitutionGoal::tryNext()
            In that case the calling derivation should just do a
            build. */
         amDone(hasSubstitute ? ecFailed : ecNoSubstituters);
+
+        if (hasSubstitute) {
+            worker.failedSubstitutions++;
+            worker.updateProgress();
+        }
+
         return;
     }
 
@@ -3611,6 +3648,7 @@ static bool working = false;
 
 Worker::Worker(LocalStore & store)
     : act(actRealise)
+    , actDerivations(actBuilds)
     , actSubstitutions(actCopyPaths)
     , store(store)
 {

src/libutil/logging.hh

@@ -19,6 +19,8 @@ typedef enum {
     actDownload = 101,
     actRealise = 102,
     actCopyPaths = 103,
+    actBuilds = 104,
+    actBuild = 105,
 } ActivityType;
 
 class Activity
@@ -36,10 +38,7 @@ public:
 };
 
 typedef enum {
-    evBuildCreated = 0,
-    evBuildStarted = 1,
     evBuildOutput = 2,
-    evBuildFinished = 3,
 
     evStartActivity = 1000,
     evStopActivity = 1001,

src/nix/progress-bar.cc

@@ -23,6 +23,7 @@ private:
         uint64_t done = 0;
         uint64_t expected = 0;
         uint64_t running = 0;
+        uint64_t failed = 0;
         std::map<ActivityType, uint64_t> expectedByType;
     };
 
@@ -31,15 +32,11 @@ private:
         std::map<Activity::t, std::list<ActInfo>::iterator> its;
         uint64_t done = 0;
         uint64_t expected = 0;
+        uint64_t failed = 0;
     };
 
     struct State
     {
-        std::map<Activity::t, Path> builds;
-        std::set<Activity::t> runningBuilds;
-        uint64_t succeededBuilds = 0;
-        uint64_t failedBuilds = 0;
-
         std::list<ActInfo> activities;
         std::map<Activity::t, std::list<ActInfo>::iterator> its;
 
@@ -62,7 +59,10 @@ public:
     ~ProgressBar()
     {
         auto state(state_.lock());
+        std::string status = getStatus(*state);
         writeToStderr("\r\e[K");
+        if (status != "")
+            writeToStderr("[" + status + "]\n");
     }
 
     void log(Verbosity lvl, const FormatOrString & fs) override
@@ -91,6 +91,7 @@ public:
         if (i != state.its.end()) {
             auto & act = state.activitiesByType[i->second->type];
             act.done += i->second->done;
+            act.failed += i->second->failed;
 
             for (auto & j : i->second->expectedByType)
                 state.activitiesByType[j.first].expected -= j.second;
@@ -139,7 +140,7 @@ public:
             if (i != state.activities.rend()) {
                 line += i->s;
                 if (!i->s2.empty()) {
-                    line += ": ";
+                    if (!i->s.empty()) line += ": ";
                     line += i->s2;
                 }
             }
@@ -155,42 +156,57 @@ public:
 
         std::string res;
 
-        auto add = [&](const std::string & s) {
+        auto renderActivity = [&](ActivityType type, const std::string & itemFmt, const std::string & numberFmt, double unit) {
-            if (!res.empty()) res += ", ";
-            res += s;
-        };
-
-        if (state.failedBuilds) {
-            add(fmt(ANSI_RED "%d failed" ANSI_NORMAL, state.failedBuilds));
-        }
-
-        if (!state.builds.empty() || state.succeededBuilds)
-        {
-            if (!res.empty()) res += ", ";
-            if (!state.runningBuilds.empty())
-                res += fmt(ANSI_BLUE "%d" "/" ANSI_NORMAL, state.runningBuilds.size());
-            res += fmt(ANSI_GREEN "%d/%d built" ANSI_NORMAL,
-                state.succeededBuilds, state.succeededBuilds + state.builds.size());
-        }
-
-        auto showActivity = [&](ActivityType type, const std::string & f, double unit) {
             auto & act = state.activitiesByType[type];
-            uint64_t done = act.done, expected = act.done, running = 0;
+            uint64_t done = act.done, expected = act.done, running = 0, failed = act.failed;
             for (auto & j : act.its) {
                 done += j.second->done;
                 expected += j.second->expected;
                 running += j.second->running;
+                failed += j.second->failed;
             }
 
             expected = std::max(expected, act.expected);
 
-            if (done || expected)
+            std::string s;
-                add(fmt(f, done / unit, expected / unit, running));
+
+            if (running || done || expected || failed) {
+                if (running)
+                    s = fmt(ANSI_BLUE + numberFmt + ANSI_NORMAL "/" ANSI_GREEN + numberFmt + ANSI_NORMAL "/" + numberFmt,
+                        running / unit, done / unit, expected / unit);
+                else if (expected != done)
+                    s = fmt(ANSI_GREEN + numberFmt + ANSI_NORMAL "/" + numberFmt,
+                        done / unit, expected / unit);
+                else
+                    s = fmt(done ? ANSI_GREEN + numberFmt + ANSI_NORMAL : numberFmt, done / unit);
+                s = fmt(itemFmt, s);
+
+                if (failed)
+                    s += fmt(" (" ANSI_RED "%d failed" ANSI_NORMAL ")", failed / unit);
+            }
+
+            return s;
         };
 
-        showActivity(actCopyPaths, ANSI_BLUE "%3$d" ANSI_NORMAL "/" ANSI_GREEN "%1$d" ANSI_NORMAL "/%2$d copied", 1);
+        auto showActivity = [&](ActivityType type, const std::string & itemFmt, const std::string & numberFmt, double unit) {
-        showActivity(actDownload, "%1$.1f/%2$.1f MiB DL", MiB);
+            auto s = renderActivity(type, itemFmt, numberFmt, unit);
-        showActivity(actCopyPath, "%1$.1f/%2$.1f MiB copied", MiB);
+            if (s.empty()) return;
+            if (!res.empty()) res += ", ";
+            res += s;
+        };
+
+        showActivity(actBuilds, "%s built", "%d", 1);
+
+        auto s1 = renderActivity(actCopyPaths, "%s copied", "%d", 1);
+        auto s2 = renderActivity(actCopyPath, "%s MiB", "%.1f", MiB);
+
+        if (!s1.empty() || !s2.empty()) {
+            if (!res.empty()) res += ", ";
+            if (s1.empty()) res += "0 copied"; else res += s1;
+            if (!s2.empty()) { res += " ("; res += s2; res += ')'; }
+        }
+
+        showActivity(actDownload, "%s MiB DL", "%.1f", MiB);
 
         return res;
     }
@@ -216,6 +232,7 @@ public:
             actInfo.done = ev.getI(1);
             actInfo.expected = ev.getI(2);
             actInfo.running = ev.getI(3);
+            actInfo.failed = ev.getI(4);
         }
 
         if (ev.type == evSetExpected) {
@@ -229,35 +246,11 @@ public:
             state->activitiesByType[type].expected += j;
         }
 
-        if (ev.type == evBuildCreated) {
-            state->builds[ev.getI(0)] = ev.getS(1);
-        }
-
-        if (ev.type == evBuildStarted) {
-            Activity::t act = ev.getI(0);
-            state->runningBuilds.insert(act);
-            auto name = storePathToName(state->builds[act]);
-            if (hasSuffix(name, ".drv"))
-                name.resize(name.size() - 4);
-            createActivity(*state, act, fmt("building " ANSI_BOLD "%s" ANSI_NORMAL, name));
-        }
-
-        if (ev.type == evBuildFinished) {
-            Activity::t act = ev.getI(0);
-            if (ev.getI(1)) {
-                if (state->runningBuilds.count(act))
-                    state->succeededBuilds++;
-            } else
-                state->failedBuilds++;
-            state->runningBuilds.erase(act);
-            state->builds.erase(act);
-            deleteActivity(*state, act);
-        }
-
         if (ev.type == evBuildOutput) {
             Activity::t act = ev.getI(0);
-            assert(state->runningBuilds.count(act));
+            auto s = trim(ev.getS(1));
-            updateActivity(*state, act, ev.getS(1));
+            if (!s.empty())
+                updateActivity(*state, act, s);
         }
 
         update(*state);