Improve progress indicator

NixOS · May 16, 2017 · b01d622 · b01d622
1 parent e80257f
commit b01d622
Show file tree

Hide file tree

Showing 26 changed files with 339 additions and 168 deletions.
diff --git a/src/libexpr/eval.cc b/src/libexpr/eval.cc
@@ -642,7 +642,7 @@ void EvalState::evalFile(const Path & path, Value & v)
         return;
     }
 
-    Activity act(*logger, lvlTalkative, format("evaluating file ‘%1%’") % path2);
+    printTalkative("evaluating file ‘%1%’", path2);
     Expr * e = parseExprFromFile(checkSourcePath(path2));
     try {
         eval(e, v);

diff --git a/src/libexpr/get-drvs.cc b/src/libexpr/get-drvs.cc
@@ -289,7 +289,7 @@ static void getDerivations(EvalState & state, Value & vIn,
            bound to the attribute with the "lower" name should take
            precedence). */
         for (auto & i : v.attrs->lexicographicOrder()) {
-            Activity act(*logger, lvlDebug, format("evaluating attribute ‘%1%’") % i->name);
+            debug("evaluating attribute ‘%1%’", i->name);
             if (!std::regex_match(std::string(i->name), attrRegex))
                 continue;
             string pathPrefix2 = addToPath(pathPrefix, i->name);
@@ -310,7 +310,6 @@ static void getDerivations(EvalState & state, Value & vIn,
 
     else if (v.isList()) {
         for (unsigned int n = 0; n < v.listSize(); ++n) {
-            Activity act(*logger, lvlDebug, "evaluating list element");
             string pathPrefix2 = addToPath(pathPrefix, (format("%1%") % n).str());
             if (getDerivation(state, *v.listElems()[n], pathPrefix2, drvs, done, ignoreAssertionFailures))
                 getDerivations(state, *v.listElems()[n], pathPrefix2, autoArgs, drvs, done, ignoreAssertionFailures);

diff --git a/src/libexpr/primops.cc b/src/libexpr/primops.cc
@@ -127,7 +127,7 @@ static void prim_scopedImport(EvalState & state, const Pos & pos, Value * * args
                 env->values[displ++] = attr.value;
             }
 
-            Activity act(*logger, lvlTalkative, format("evaluating file ‘%1%’") % path);
+            printTalkative("evaluating file ‘%1%’", path);
             Expr * e = state.parseExprFromFile(resolveExprPath(path), staticEnv);
 
             e->eval(state, *env, v);
@@ -326,8 +326,6 @@ typedef list<Value *> ValueList;
 
 static void prim_genericClosure(EvalState & state, const Pos & pos, Value * * args, Value & v)
 {
-    Activity act(*logger, lvlDebug, "finding dependencies");
-
     state.forceAttrs(*args[0], pos);
 
     /* Get the start set. */
@@ -499,8 +497,6 @@ void prim_valueSize(EvalState & state, const Pos & pos, Value * * args, Value &
    derivation. */
 static void prim_derivationStrict(EvalState & state, const Pos & pos, Value * * args, Value & v)
 {
-    Activity act(*logger, lvlVomit, "evaluating derivation");
-
     state.forceAttrs(*args[0], pos);
 
     /* Figure out the name first (for stack backtraces). */
@@ -544,7 +540,7 @@ static void prim_derivationStrict(EvalState & state, const Pos & pos, Value * *
     for (auto & i : args[0]->attrs->lexicographicOrder()) {
         if (i->name == state.sIgnoreNulls) continue;
         string key = i->name;
-        Activity act(*logger, lvlVomit, format("processing attribute ‘%1%’") % key);
+        vomit("processing attribute ‘%1%’", key);
 
         auto handleHashMode = [&](const std::string & s) {
             if (s == "recursive") outputHashRecursive = true;

diff --git a/src/libexpr/primops/fetchgit.cc b/src/libexpr/primops/fetchgit.cc
@@ -17,7 +17,7 @@ Path exportGit(ref<Store> store, const std::string & uri, const std::string & re
         runProgram("git", true, { "init", "--bare", cacheDir });
     }
 
-    Activity act(*logger, lvlInfo, format("fetching Git repository ‘%s’") % uri);
+    //Activity act(*logger, lvlInfo, format("fetching Git repository ‘%s’") % uri);
 
     std::string localRef = "pid-" + std::to_string(getpid());
     Path localRefFile = cacheDir + "/refs/heads/" + localRef;

diff --git a/src/libstore/build.cc b/src/libstore/build.cc
@@ -120,6 +120,8 @@ class Goal : public std::enable_shared_from_this<Goal>
     /* Whether the goal is finished. */
     ExitCode exitCode;
 
+    Activity act;
+
     Goal(Worker & worker) : worker(worker)
     {
         nrFailed = nrNoSubstituters = nrIncompleteClosure = 0;
@@ -168,7 +170,8 @@ class Goal : public std::enable_shared_from_this<Goal>
     virtual string key() = 0;
 
 protected:
-    void amDone(ExitCode result);
+
+    virtual void amDone(ExitCode result);
 };
 
 
@@ -902,6 +905,12 @@ class DerivationGoal : public Goal
 
     void repairClosure();
 
+    void amDone(ExitCode result)
+    {
+        logger->event(evBuildFinished, act, result == ecSuccess);
+        Goal::amDone(result);
+    }
+
     void done(BuildResult::Status status, const string & msg = "");
 };
 
@@ -920,6 +929,8 @@ DerivationGoal::DerivationGoal(const Path & drvPath, const StringSet & wantedOut
     state = &DerivationGoal::getDerivation;
     name = (format("building of ‘%1%’") % drvPath).str();
     trace("created");
+
+    logger->event(evBuildCreated, act, drvPath);
 }
 
 
@@ -935,6 +946,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);
+
     /* Prevent the .chroot directory from being
        garbage-collected. (See isActiveTempFile() in gc.cc.) */
     worker.store.addTempRoot(drvPath);
@@ -2112,6 +2125,8 @@ void DerivationGoal::startBuilder()
         }
         debug(msg);
     }
+
+    logger->event(evBuildStarted, act);
 }
 
 
@@ -2857,7 +2872,7 @@ void DerivationGoal::registerOutputs()
            contained in it.  Compute the SHA-256 NAR hash at the same
            time.  The hash is stored in the database so that we can
            verify later on whether nobody has messed with the store. */
-        Activity act(*logger, lvlTalkative, format("scanning for references inside ‘%1%’") % path);
+        debug("scanning for references inside ‘%1%’", path);
         HashResult hash;
         PathSet references = scanForReferences(actualPath, allPaths, hash);
 
@@ -3130,6 +3145,7 @@ void DerivationGoal::flushLine()
         logTail.push_back(currentLogLine);
         if (logTail.size() > settings.logLines) logTail.pop_front();
     }
+    logger->event(evBuildOutput, act, currentLogLine);
     currentLogLine = "";
     currentLogLinePos = 0;
 }
@@ -3244,6 +3260,12 @@ class SubstitutionGoal : public Goal
     void handleEOF(int fd);
 
     Path getStorePath() { return storePath; }
+
+    void amDone(ExitCode result)
+    {
+        logger->event(evSubstitutionFinished, act, result == ecSuccess);
+        Goal::amDone(result);
+    }
 };
 
 
@@ -3256,6 +3278,7 @@ SubstitutionGoal::SubstitutionGoal(const Path & storePath, Worker & worker, bool
     state = &SubstitutionGoal::init;
     name = (format("substitution of ‘%1%’") % storePath).str();
     trace("created");
+    logger->event(evSubstitutionCreated, act, storePath);
 }
 
 
@@ -3391,6 +3414,8 @@ void SubstitutionGoal::tryToRun()
 
     printInfo(format("fetching path ‘%1%’...") % storePath);
 
+    logger->event(evSubstitutionStarted, act);
+
     outPipe.create();
 
     promise = std::promise<void>();
@@ -3637,7 +3662,7 @@ void Worker::run(const Goals & _topGoals)
 {
     for (auto & i : _topGoals) topGoals.insert(i);
 
-    Activity act(*logger, lvlDebug, "entered goal loop");
+    debug("entered goal loop");
 
     while (1) {
 

diff --git a/src/libstore/builtins.cc b/src/libstore/builtins.cc
@@ -28,9 +28,6 @@ void builtinFetchurl(const BasicDerivation & drv, const std::string & netrcData)
         DownloadRequest request(url);
         request.verifyTLS = false;
 
-        /* Show a progress indicator, even though stderr is not a tty. */
-        request.showProgress = DownloadRequest::yes;
-
         /* Note: have to use a fresh downloader here because we're in
            a forked process. */
         auto data = makeDownloader()->download(request);

diff --git a/src/libstore/download.cc b/src/libstore/download.cc
@@ -63,17 +63,14 @@ struct CurlDownloader : public Downloader
         CurlDownloader & downloader;
         DownloadRequest request;
         DownloadResult result;
+        Activity act;
         bool done = false; // whether either the success or failure function has been called
         std::function<void(const DownloadResult &)> success;
         std::function<void(std::exception_ptr exc)> failure;
         CURL * req = 0;
         bool active = false; // whether the handle has been added to the multi object
         std::string status;
 
-        bool showProgress = false;
-        double prevProgressTime{0}, startTime{0};
-        unsigned int moveBack{1};
-
         unsigned int attempt = 0;
 
         /* Don't start this download until the specified time point
@@ -87,12 +84,10 @@ struct CurlDownloader : public Downloader
         DownloadItem(CurlDownloader & downloader, const DownloadRequest & request)
             : downloader(downloader), request(request)
         {
-            showProgress =
-                request.showProgress == DownloadRequest::yes ||
-                (request.showProgress == DownloadRequest::automatic && isatty(STDERR_FILENO));
-
             if (!request.expectedETag.empty())
                 requestHeaders = curl_slist_append(requestHeaders, ("If-None-Match: " + request.expectedETag).c_str());
+
+            logger->event(evDownloadCreated, act, request.uri);
         }
 
         ~DownloadItem()
@@ -109,6 +104,7 @@ struct CurlDownloader : public Downloader
             } catch (...) {
                 ignoreException();
             }
+            logger->event(evDownloadDestroyed, act);
         }
 
         template<class T>
@@ -171,19 +167,7 @@ struct CurlDownloader : public Downloader
 
         int progressCallback(double dltotal, double dlnow)
         {
-            if (showProgress) {
-                double now = getTime();
-                if (prevProgressTime <= now - 1) {
-                    string s = (format(" [%1$.0f/%2$.0f KiB, %3$.1f KiB/s]")
-                        % (dlnow / 1024.0)
-                        % (dltotal / 1024.0)
-                        % (now == startTime ? 0 : dlnow / 1024.0 / (now - startTime))).str();
-                    std::cerr << "\e[" << moveBack << "D" << s;
-                    moveBack = s.size();
-                    std::cerr.flush();
-                    prevProgressTime = now;
-                }
-            }
+            logger->event(evDownloadProgress, act, dltotal, dlnow);
             return _isInterrupted;
         }
 
@@ -201,13 +185,6 @@ struct CurlDownloader : public Downloader
 
         void init()
         {
-            // FIXME: handle parallel downloads.
-            if (showProgress) {
-                std::cerr << (format("downloading ‘%1%’... ") % request.uri);
-                std::cerr.flush();
-                startTime = getTime();
-            }
-
             if (!req) req = curl_easy_init();
 
             curl_easy_reset(req);
@@ -263,10 +240,6 @@ struct CurlDownloader : public Downloader
 
         void finish(CURLcode code)
         {
-            if (showProgress)
-                //std::cerr << "\e[" << moveBack << "D\e[K\n";
-                std::cerr << "\n";
-
             long httpStatus = 0;
             curl_easy_getinfo(req, CURLINFO_RESPONSE_CODE, &httpStatus);
 
@@ -292,6 +265,7 @@ struct CurlDownloader : public Downloader
                 try {
                     result.data = decodeContent(encoding, ref<std::string>(result.data));
                     callSuccess(success, failure, const_cast<const DownloadResult &>(result));
+                    logger->event(evDownloadSucceeded, act, result.data->size());
                 } catch (...) {
                     done = true;
                     callFailure(failure, std::current_exception());

diff --git a/src/libstore/download.hh b/src/libstore/download.hh
@@ -13,7 +13,6 @@ struct DownloadRequest
     std::string uri;
     std::string expectedETag;
     bool verifyTLS = true;
-    enum { yes, no, automatic } showProgress = yes;
     bool head = false;
     size_t tries = 5;
     unsigned int baseRetryTimeMs = 250;

diff --git a/src/libstore/export-import.cc b/src/libstore/export-import.cc
@@ -30,13 +30,13 @@ void Store::exportPaths(const Paths & paths, Sink & sink)
     std::reverse(sorted.begin(), sorted.end());
 
     std::string doneLabel("paths exported");
-    logger->incExpected(doneLabel, sorted.size());
+    //logger->incExpected(doneLabel, sorted.size());
 
     for (auto & path : sorted) {
-        Activity act(*logger, lvlInfo, format("exporting path ‘%s’") % path);
+        //Activity act(*logger, lvlInfo, format("exporting path ‘%s’") % path);
         sink << 1;
         exportPath(path, sink);
-        logger->incProgress(doneLabel);
+        //logger->incProgress(doneLabel);
     }
 
     sink << 0;
@@ -81,7 +81,7 @@ Paths Store::importPaths(Source & source, std::shared_ptr<FSAccessor> accessor,
 
         info.path = readStorePath(*this, source);
 
-        Activity act(*logger, lvlInfo, format("importing path ‘%s’") % info.path);
+        //Activity act(*logger, lvlInfo, format("importing path ‘%s’") % info.path);
 
         info.references = readStorePaths<PathSet>(*this, source);
 

diff --git a/src/libstore/gc.cc b/src/libstore/gc.cc
@@ -615,7 +615,7 @@ void LocalStore::tryToDelete(GCState & state, const Path & path)
     auto realPath = realStoreDir + "/" + baseNameOf(path);
     if (realPath == linksDir || realPath == trashDir) return;
 
-    Activity act(*logger, lvlDebug, format("considering whether to delete ‘%1%’") % path);
+    //Activity act(*logger, lvlDebug, format("considering whether to delete ‘%1%’") % path);
 
     if (!isStorePath(path) || !isValidPath(path)) {
         /* A lock file belonging to a path that we're building right

diff --git a/src/libstore/http-binary-cache-store.cc b/src/libstore/http-binary-cache-store.cc
@@ -50,7 +50,6 @@ class HttpBinaryCacheStore : public BinaryCacheStore
     {
         try {
             DownloadRequest request(cacheUri + "/" + path);
-            request.showProgress = DownloadRequest::no;
             request.head = true;
             request.tries = 5;
             getDownloader()->download(request);
@@ -76,7 +75,6 @@ class HttpBinaryCacheStore : public BinaryCacheStore
         std::function<void(std::exception_ptr exc)> failure) override
     {
         DownloadRequest request(cacheUri + "/" + path);
-        request.showProgress = DownloadRequest::no;
         request.tries = 8;
 
         getDownloader()->enqueueDownload(request,

diff --git a/src/libstore/optimise-store.cc b/src/libstore/optimise-store.cc
@@ -240,7 +240,7 @@ void LocalStore::optimiseStore(OptimiseStats & stats)
     for (auto & i : paths) {
         addTempRoot(i);
         if (!isValidPath(i)) continue; /* path was GC'ed, probably */
-        Activity act(*logger, lvlChatty, format("hashing files in ‘%1%’") % i);
+        //Activity act(*logger, lvlChatty, format("hashing files in ‘%1%’") % i);
         optimisePath_(stats, realStoreDir + "/" + baseNameOf(i), inodeHash);
     }
 }

diff --git a/src/libstore/store-api.cc b/src/libstore/store-api.cc
@@ -822,7 +822,7 @@ void copyPaths(ref<Store> from, ref<Store> to, const PathSet & storePaths,
 
     std::string copiedLabel = "copied";
 
-    logger->setExpected(copiedLabel, missing.size());
+    //logger->setExpected(copiedLabel, missing.size());
 
     ThreadPool pool;
 
@@ -838,13 +838,14 @@ void copyPaths(ref<Store> from, ref<Store> to, const PathSet & storePaths,
             checkInterrupt();
 
             if (!to->isValidPath(storePath)) {
-                Activity act(*logger, lvlInfo, format("copying ‘%s’...") % storePath);
+                //Activity act(*logger, lvlInfo, format("copying ‘%s’...") % storePath);
 
                 copyStorePath(from, to, storePath, false, dontCheckSigs);
 
-                logger->incProgress(copiedLabel);
+                //logger->incProgress(copiedLabel);
             } else
-                logger->incExpected(copiedLabel, -1);
+                ;
+                //logger->incExpected(copiedLabel, -1);
         });
 
     pool.process();