From 6d4e54e07c5fd6dafed47c805e0ad6310b08f71c Mon Sep 17 00:00:00 2001 From: Qyriad Date: Wed, 19 Jun 2024 20:42:50 -0600 Subject: [PATCH 1/4] Revert "state commit" This reverts commit 619cfa9fecec3d490630ef70dfeb8bd01d85a7c7. --- src/libmain/progress-bar.cc | 186 +++++++++++------------------------- src/libutil/logging.hh | 32 ------- 2 files changed, 56 insertions(+), 162 deletions(-) diff --git a/src/libmain/progress-bar.cc b/src/libmain/progress-bar.cc index a8e4c0133..b837eee8a 100644 --- a/src/libmain/progress-bar.cc +++ b/src/libmain/progress-bar.cc @@ -1,6 +1,4 @@ #include "progress-bar.hh" -#include "escape-string.hh" -#include "logging.hh" #include "sync.hh" #include "store-api.hh" #include "names.hh" @@ -41,85 +39,48 @@ static std::string_view storePathToName(std::string_view path) // 100 years ought to be enough for anyone (yet sufficiently smaller than max() to not cause signed integer overflow). constexpr const auto A_LONG_TIME = std::chrono::duration_cast(100 * 365 * 86400s); - -struct ActInfo -{ - using TimePoint = std::chrono::time_point; - - std::string s; - std::string lastLine; - std::string phase; - ActivityType type = actUnknown; - uint64_t done = 0; - uint64_t expected = 0; - uint64_t running = 0; - uint64_t failed = 0; - std::map expectedByType; - bool visible = true; - ActivityId parent; - std::optional name; - TimePoint startTime; - - std::string to_string() const - { - EscapeStringOptions escapeOptions{ - .escapeNonPrinting = true, - }; - auto const escapedS = escapeString(s, escapeOptions); - auto const escapedLastLine = escapeString(lastLine, escapeOptions); - auto const escapedPhase = escapeString(phase, escapeOptions); - auto const typeS = activityTypeToString(type); - - return fmt( - "ActInfo {\n s = %s,\n lastLine = %s,\n phase = %s,\n type = %s,\n done = %d\n expected = %d,\n running = %d,\n failed = %d,\n parent = %d,\n name = %s,\n}", - escapedS, - escapedLastLine, - escapedPhase, - typeS, - done, - expected, - running, - failed, - parent, - name.value_or("") - ); - } -}; - -using ActInfoIterator = std::list::iterator; - -struct ActivitiesByType -{ - std::map its; - uint64_t done = 0; - uint64_t expected = 0; - uint64_t failed = 0; -}; - -struct BarState -{ - std::list activities; - std::map its; - - std::map activitiesByType; - - uint64_t filesLinked = 0; - uint64_t bytesLinked = 0; - uint64_t corruptedPaths = 0; - uint64_t untrustedPaths = 0; - - bool active = true; - bool paused = false; - bool haveUpdate = true; -}; - class ProgressBar : public Logger { private: - //using ActInfo = ActInfo; - using ActivitiesByType = ActivitiesByType; - using State = BarState; + struct ActInfo + { + std::string s, lastLine, phase; + ActivityType type = actUnknown; + uint64_t done = 0; + uint64_t expected = 0; + uint64_t running = 0; + uint64_t failed = 0; + std::map expectedByType; + bool visible = true; + ActivityId parent; + std::optional name; + std::chrono::time_point startTime; + }; + + struct ActivitiesByType + { + std::map::iterator> its; + uint64_t done = 0; + uint64_t expected = 0; + uint64_t failed = 0; + }; + + struct State + { + std::list activities; + std::map::iterator> its; + + std::map activitiesByType; + + uint64_t filesLinked = 0, bytesLinked = 0; + + uint64_t corruptedPaths = 0, untrustedPaths = 0; + + bool active = true; + bool paused = false; + bool haveUpdate = true; + }; Sync state_; @@ -454,13 +415,6 @@ public: std::string getStatus(State & state) { constexpr auto MiB = 1024.0 * 1024.0; - //this->cout("getStatus(): we have %d activities", state.activities.size()); - //std::cerr << "\ngetStatus(): we have " << state.activities.size() << "\n"; - - if (!state.activities.empty()) { - ActInfo const & firstActivity = state.activities.front(); - std::cerr << "\ngetStatus(): " << firstActivity.to_string() << "\n"; - } std::string res; @@ -479,49 +433,21 @@ public: std::string s; if (running || done || expected || failed) { - if (running) { - if (expected != 0) { - auto const runningPart = fmt(numberFmt, running / unit); - auto const donePart = fmt(numberFmt, done / unit); - auto const expectedPart = fmt(numberFmt, expected / unit); - s = fmt( - ANSI_BLUE "%s" ANSI_NORMAL "/" ANSI_GREEN "%s" ANSI_NORMAL "/%s", - runningPart, - donePart, - expectedPart - ); - } else { - auto const runningPart = fmt(numberFmt, running / unit); - auto const donePart = fmt(numberFmt, done / unit); - s = fmt( - ANSI_BLUE "%s" ANSI_NORMAL "/" ANSI_GREEN "%s" ANSI_NORMAL, - runningPart, - donePart - ); - } - } else if (expected != done) { - if (expected != 0) { - auto const donePart = fmt(numberFmt, done / unit); - auto const expectedPart = fmt(numberFmt, expected / unit); - s = fmt( - ANSI_GREEN "%s" ANSI_NORMAL "/%s", - donePart, - expectedPart - ); - } else { - auto const donePart = fmt(numberFmt, done / unit); - s = fmt(ANSI_GREEN "%s" ANSI_NORMAL, donePart); - } - } else { - auto const donePart = fmt(numberFmt, done / unit); - - // We only color if `done` is non-zero. - if (done) { - s = concatStrings(ANSI_GREEN, donePart, ANSI_NORMAL); - } else { - s = donePart; - } - } + if (running) + if (expected != 0) + s = fmt(ANSI_BLUE + numberFmt + ANSI_NORMAL "/" ANSI_GREEN + numberFmt + ANSI_NORMAL "/" + numberFmt, + running / unit, done / unit, expected / unit); + else + s = fmt(ANSI_BLUE + numberFmt + ANSI_NORMAL "/" ANSI_GREEN + numberFmt + ANSI_NORMAL, + running / unit, done / unit); + else if (expected != done) + if (expected != 0) + s = fmt(ANSI_GREEN + numberFmt + ANSI_NORMAL "/" + numberFmt, + done / unit, expected / unit); + else + s = fmt(ANSI_GREEN + numberFmt + ANSI_NORMAL, done / unit); + else + s = fmt(done ? ANSI_GREEN + numberFmt + ANSI_NORMAL : numberFmt, done / unit); s = fmt(itemFmt, s); if (failed) @@ -532,10 +458,10 @@ public: }; auto showActivity = [&](ActivityType type, const std::string & itemFmt, const std::string & numberFmt = "%d", double unit = 1) { - auto rendered = renderActivity(type, itemFmt, numberFmt, unit); - if (rendered.empty()) return; + auto s = renderActivity(type, itemFmt, numberFmt, unit); + if (s.empty()) return; if (!res.empty()) res += ", "; - res += rendered; + res += s; }; showActivity(actBuilds, "%s built"); diff --git a/src/libutil/logging.hh b/src/libutil/logging.hh index 44be85da4..64be8bc62 100644 --- a/src/libutil/logging.hh +++ b/src/libutil/logging.hh @@ -23,38 +23,6 @@ typedef enum { actBuildWaiting = 111, } ActivityType; -constexpr std::string_view activityTypeToString(ActivityType const & actType) -{ - switch (actType) { - case actUnknown: - return "Unknown"; - case actCopyPath: - return "CopyPath"; - case actFileTransfer: - return "FileTransfer"; - case actRealise: - return "Realise"; - case actCopyPaths: - return "CopyPaths"; - case actBuilds: - return "Builds"; - case actBuild: - return "Build"; - case actOptimiseStore: - return "OptimiseStore"; - case actVerifyPaths: - return "VerifyPaths"; - case actSubstitute: - return "Substitute"; - case actQueryPathInfo: - return "QueryPathInfo"; - case actPostBuildHook: - return "PostBuildHook"; - case actBuildWaiting: - return "BuildWaiting"; - } -} - typedef enum { resFileLinked = 100, resBuildLogLine = 101, From 51336e3bf42dd0ba94a0f964104fdcce076f0045 Mon Sep 17 00:00:00 2001 From: Qyriad Date: Wed, 19 Jun 2024 20:56:28 -0600 Subject: [PATCH 2/4] extract ProgressBar declaration into its header file Change-Id: Ica9e2ec41d99eaa196a0d535501edf45c589b2b6 --- src/libmain/progress-bar.cc | 829 +++++++++++++++++------------------- src/libmain/progress-bar.hh | 121 ++++++ 2 files changed, 503 insertions(+), 447 deletions(-) diff --git a/src/libmain/progress-bar.cc b/src/libmain/progress-bar.cc index b837eee8a..b3466a860 100644 --- a/src/libmain/progress-bar.cc +++ b/src/libmain/progress-bar.cc @@ -36,500 +36,435 @@ static std::string_view storePathToName(std::string_view path) return i == std::string::npos ? base.substr(0, 0) : base.substr(i + 1); } -// 100 years ought to be enough for anyone (yet sufficiently smaller than max() to not cause signed integer overflow). -constexpr const auto A_LONG_TIME = std::chrono::duration_cast(100 * 365 * 86400s); -class ProgressBar : public Logger +ProgressBar::~ProgressBar() { -private: + stop(); +} - struct ActInfo +/* Called by destructor, can't be overridden */ +void ProgressBar::stop() +{ { - std::string s, lastLine, phase; - ActivityType type = actUnknown; - uint64_t done = 0; - uint64_t expected = 0; - uint64_t running = 0; - uint64_t failed = 0; - std::map expectedByType; - bool visible = true; - ActivityId parent; - std::optional name; - std::chrono::time_point startTime; - }; - - struct ActivitiesByType - { - std::map::iterator> its; - uint64_t done = 0; - uint64_t expected = 0; - uint64_t failed = 0; - }; - - struct State - { - std::list activities; - std::map::iterator> its; - - std::map activitiesByType; - - uint64_t filesLinked = 0, bytesLinked = 0; - - uint64_t corruptedPaths = 0, untrustedPaths = 0; - - bool active = true; - bool paused = false; - bool haveUpdate = true; - }; - - Sync state_; - - std::thread updateThread; - - std::condition_variable quitCV, updateCV; - - bool printBuildLogs = false; - bool isTTY; - -public: - - ProgressBar(bool isTTY) - : isTTY(isTTY) - { - state_.lock()->active = isTTY; - updateThread = std::thread([&]() { - auto state(state_.lock()); - auto nextWakeup = A_LONG_TIME; - while (state->active) { - if (!state->haveUpdate) - state.wait_for(updateCV, nextWakeup); - nextWakeup = draw(*state); - state.wait_for(quitCV, std::chrono::milliseconds(50)); - } - }); - } - - ~ProgressBar() - { - stop(); - } - - /* Called by destructor, can't be overridden */ - void stop() override final - { - { - auto state(state_.lock()); - if (!state->active) return; - state->active = false; - writeToStderr("\r\e[K"); - updateCV.notify_one(); - quitCV.notify_one(); - } - updateThread.join(); - } - - void pause() override { - state_.lock()->paused = true; + auto state(state_.lock()); + if (!state->active) return; + state->active = false; writeToStderr("\r\e[K"); - } - - void resume() override { - state_.lock()->paused = false; - writeToStderr("\r\e[K"); - state_.lock()->haveUpdate = true; updateCV.notify_one(); + quitCV.notify_one(); + } + updateThread.join(); +} + +void ProgressBar::pause() +{ + state_.lock()->paused = true; + writeToStderr("\r\e[K"); +} + +void ProgressBar::resume() +{ + state_.lock()->paused = false; + writeToStderr("\r\e[K"); + state_.lock()->haveUpdate = true; + updateCV.notify_one(); +} + +bool ProgressBar::isVerbose() +{ + return printBuildLogs; +} + +void ProgressBar::log(Verbosity lvl, std::string_view s) +{ + if (lvl > verbosity) return; + auto state(state_.lock()); + log(*state, lvl, s); +} + +void ProgressBar::logEI(const ErrorInfo & ei) +{ + auto state(state_.lock()); + + std::stringstream oss; + showErrorInfo(oss, ei, loggerSettings.showTrace.get()); + + log(*state, ei.level, oss.str()); +} + +void ProgressBar::log(State & state, Verbosity lvl, std::string_view s) +{ + if (state.active) { + writeToStderr("\r\e[K" + filterANSIEscapes(s, !isTTY) + ANSI_NORMAL "\n"); + draw(state); + } else { + auto s2 = s + ANSI_NORMAL "\n"; + if (!isTTY) s2 = filterANSIEscapes(s2, true); + writeToStderr(s2); + } +} + +void ProgressBar::startActivity( + ActivityId act, + Verbosity lvl, + ActivityType type, + const std::string & s, + const Fields & fields, + ActivityId parent +) +{ + auto state(state_.lock()); + + if (lvl <= verbosity && !s.empty() && type != actBuildWaiting) + log(*state, lvl, s + "..."); + + state->activities.emplace_back(ActInfo { + .s = s, + .type = type, + .parent = parent, + .startTime = std::chrono::steady_clock::now() + }); + auto i = std::prev(state->activities.end()); + state->its.emplace(act, i); + state->activitiesByType[type].its.emplace(act, i); + + if (type == actBuild) { + std::string name(storePathToName(getS(fields, 0))); + if (name.ends_with(".drv")) + name = name.substr(0, name.size() - 4); + i->s = fmt("building " ANSI_BOLD "%s" ANSI_NORMAL, name); + auto machineName = getS(fields, 1); + if (machineName != "") + i->s += fmt(" on " ANSI_BOLD "%s" ANSI_NORMAL, machineName); + + // Used to be curRound and nrRounds, but the + // implementation was broken for a long time. + if (getI(fields, 2) != 1 || getI(fields, 3) != 1) { + throw Error("log message indicated repeating builds, but this is not currently implemented"); + } + i->name = DrvName(name).name; } - bool isVerbose() override - { - return printBuildLogs; + if (type == actSubstitute) { + auto name = storePathToName(getS(fields, 0)); + auto sub = getS(fields, 1); + i->s = fmt( + sub.starts_with("local") + ? "copying " ANSI_BOLD "%s" ANSI_NORMAL " from %s" + : "fetching " ANSI_BOLD "%s" ANSI_NORMAL " from %s", + name, sub); } - void log(Verbosity lvl, std::string_view s) override - { - if (lvl > verbosity) return; - auto state(state_.lock()); - log(*state, lvl, s); + if (type == actPostBuildHook) { + auto name = storePathToName(getS(fields, 0)); + if (name.ends_with(".drv")) + name = name.substr(0, name.size() - 4); + i->s = fmt("post-build " ANSI_BOLD "%s" ANSI_NORMAL, name); + i->name = DrvName(name).name; } - void logEI(const ErrorInfo & ei) override - { - auto state(state_.lock()); - - std::stringstream oss; - showErrorInfo(oss, ei, loggerSettings.showTrace.get()); - - log(*state, ei.level, oss.str()); + if (type == actQueryPathInfo) { + auto name = storePathToName(getS(fields, 0)); + i->s = fmt("querying " ANSI_BOLD "%s" ANSI_NORMAL " on %s", name, getS(fields, 1)); } - void log(State & state, Verbosity lvl, std::string_view s) - { - if (state.active) { - writeToStderr("\r\e[K" + filterANSIEscapes(s, !isTTY) + ANSI_NORMAL "\n"); - draw(state); - } else { - auto s2 = s + ANSI_NORMAL "\n"; - if (!isTTY) s2 = filterANSIEscapes(s2, true); - writeToStderr(s2); - } + if ((type == actFileTransfer && hasAncestor(*state, actCopyPath, parent)) + || (type == actFileTransfer && hasAncestor(*state, actQueryPathInfo, parent)) + || (type == actCopyPath && hasAncestor(*state, actSubstitute, parent))) + i->visible = false; + + update(*state); +} + +/* Check whether an activity has an ancestore with the specified + type. */ +bool ProgressBar::hasAncestor(State & state, ActivityType type, ActivityId act) +{ + while (act != 0) { + auto i = state.its.find(act); + if (i == state.its.end()) break; + if (i->second->type == type) return true; + act = i->second->parent; + } + return false; +} + +void ProgressBar::stopActivity(ActivityId act) +{ + auto state(state_.lock()); + + auto i = state->its.find(act); + if (i != state->its.end()) { + + auto & actByType = state->activitiesByType[i->second->type]; + actByType.done += i->second->done; + actByType.failed += i->second->failed; + + for (auto & j : i->second->expectedByType) + state->activitiesByType[j.first].expected -= j.second; + + actByType.its.erase(act); + state->activities.erase(i->second); + state->its.erase(i); } - void startActivity(ActivityId act, Verbosity lvl, ActivityType type, - const std::string & s, const Fields & fields, ActivityId parent) override - { - auto state(state_.lock()); + update(*state); +} - if (lvl <= verbosity && !s.empty() && type != actBuildWaiting) - log(*state, lvl, s + "..."); - - state->activities.emplace_back(ActInfo { - .s = s, - .type = type, - .parent = parent, - .startTime = std::chrono::steady_clock::now() - }); - auto i = std::prev(state->activities.end()); - state->its.emplace(act, i); - state->activitiesByType[type].its.emplace(act, i); - - if (type == actBuild) { - std::string name(storePathToName(getS(fields, 0))); - if (name.ends_with(".drv")) - name = name.substr(0, name.size() - 4); - i->s = fmt("building " ANSI_BOLD "%s" ANSI_NORMAL, name); - auto machineName = getS(fields, 1); - if (machineName != "") - i->s += fmt(" on " ANSI_BOLD "%s" ANSI_NORMAL, machineName); - - // Used to be curRound and nrRounds, but the - // implementation was broken for a long time. - if (getI(fields, 2) != 1 || getI(fields, 3) != 1) { - throw Error("log message indicated repeating builds, but this is not currently implemented"); - } - i->name = DrvName(name).name; - } - - if (type == actSubstitute) { - auto name = storePathToName(getS(fields, 0)); - auto sub = getS(fields, 1); - i->s = fmt( - sub.starts_with("local") - ? "copying " ANSI_BOLD "%s" ANSI_NORMAL " from %s" - : "fetching " ANSI_BOLD "%s" ANSI_NORMAL " from %s", - name, sub); - } - - if (type == actPostBuildHook) { - auto name = storePathToName(getS(fields, 0)); - if (name.ends_with(".drv")) - name = name.substr(0, name.size() - 4); - i->s = fmt("post-build " ANSI_BOLD "%s" ANSI_NORMAL, name); - i->name = DrvName(name).name; - } - - if (type == actQueryPathInfo) { - auto name = storePathToName(getS(fields, 0)); - i->s = fmt("querying " ANSI_BOLD "%s" ANSI_NORMAL " on %s", name, getS(fields, 1)); - } - - if ((type == actFileTransfer && hasAncestor(*state, actCopyPath, parent)) - || (type == actFileTransfer && hasAncestor(*state, actQueryPathInfo, parent)) - || (type == actCopyPath && hasAncestor(*state, actSubstitute, parent))) - i->visible = false; +void ProgressBar::result(ActivityId act, ResultType type, const std::vector & fields) +{ + auto state(state_.lock()); + if (type == resFileLinked) { + state->filesLinked++; + state->bytesLinked += getI(fields, 0); update(*state); } - /* Check whether an activity has an ancestore with the specified - type. */ - bool hasAncestor(State & state, ActivityType type, ActivityId act) - { - while (act != 0) { - auto i = state.its.find(act); - if (i == state.its.end()) break; - if (i->second->type == type) return true; - act = i->second->parent; + else if (type == resBuildLogLine || type == resPostBuildLogLine) { + auto lastLine = chomp(getS(fields, 0)); + if (!lastLine.empty()) { + auto i = state->its.find(act); + assert(i != state->its.end()); + ActInfo info = *i->second; + if (printBuildLogs) { + auto suffix = "> "; + if (type == resPostBuildLogLine) { + suffix = " (post)> "; + } + log(*state, lvlInfo, ANSI_FAINT + info.name.value_or("unnamed") + suffix + ANSI_NORMAL + lastLine); + } else { + state->activities.erase(i->second); + info.lastLine = lastLine; + state->activities.emplace_back(info); + i->second = std::prev(state->activities.end()); + update(*state); + } } - return false; } - void stopActivity(ActivityId act) override - { - auto state(state_.lock()); + else if (type == resUntrustedPath) { + state->untrustedPaths++; + update(*state); + } + else if (type == resCorruptedPath) { + state->corruptedPaths++; + update(*state); + } + + else if (type == resSetPhase) { auto i = state->its.find(act); - if (i != state->its.end()) { - - auto & actByType = state->activitiesByType[i->second->type]; - actByType.done += i->second->done; - actByType.failed += i->second->failed; - - for (auto & j : i->second->expectedByType) - state->activitiesByType[j.first].expected -= j.second; - - actByType.its.erase(act); - state->activities.erase(i->second); - state->its.erase(i); - } - + assert(i != state->its.end()); + i->second->phase = getS(fields, 0); update(*state); } - void result(ActivityId act, ResultType type, const std::vector & fields) override - { - auto state(state_.lock()); - - if (type == resFileLinked) { - state->filesLinked++; - state->bytesLinked += getI(fields, 0); - update(*state); - } - - else if (type == resBuildLogLine || type == resPostBuildLogLine) { - auto lastLine = chomp(getS(fields, 0)); - if (!lastLine.empty()) { - auto i = state->its.find(act); - assert(i != state->its.end()); - ActInfo info = *i->second; - if (printBuildLogs) { - auto suffix = "> "; - if (type == resPostBuildLogLine) { - suffix = " (post)> "; - } - log(*state, lvlInfo, ANSI_FAINT + info.name.value_or("unnamed") + suffix + ANSI_NORMAL + lastLine); - } else { - state->activities.erase(i->second); - info.lastLine = lastLine; - state->activities.emplace_back(info); - i->second = std::prev(state->activities.end()); - update(*state); - } - } - } - - else if (type == resUntrustedPath) { - state->untrustedPaths++; - update(*state); - } - - else if (type == resCorruptedPath) { - state->corruptedPaths++; - update(*state); - } - - else if (type == resSetPhase) { - auto i = state->its.find(act); - assert(i != state->its.end()); - i->second->phase = getS(fields, 0); - update(*state); - } - - else if (type == resProgress) { - auto i = state->its.find(act); - assert(i != state->its.end()); - ActInfo & actInfo = *i->second; - actInfo.done = getI(fields, 0); - actInfo.expected = getI(fields, 1); - actInfo.running = getI(fields, 2); - actInfo.failed = getI(fields, 3); - update(*state); - } - - else if (type == resSetExpected) { - auto i = state->its.find(act); - assert(i != state->its.end()); - ActInfo & actInfo = *i->second; - auto type = (ActivityType) getI(fields, 0); - auto & j = actInfo.expectedByType[type]; - state->activitiesByType[type].expected -= j; - j = getI(fields, 1); - state->activitiesByType[type].expected += j; - update(*state); - } + else if (type == resProgress) { + auto i = state->its.find(act); + assert(i != state->its.end()); + ActInfo & actInfo = *i->second; + actInfo.done = getI(fields, 0); + actInfo.expected = getI(fields, 1); + actInfo.running = getI(fields, 2); + actInfo.failed = getI(fields, 3); + update(*state); } - void update(State & state) - { - state.haveUpdate = true; - updateCV.notify_one(); + else if (type == resSetExpected) { + auto i = state->its.find(act); + assert(i != state->its.end()); + ActInfo & actInfo = *i->second; + auto type = (ActivityType) getI(fields, 0); + auto & j = actInfo.expectedByType[type]; + state->activitiesByType[type].expected -= j; + j = getI(fields, 1); + state->activitiesByType[type].expected += j; + update(*state); + } +} + +void ProgressBar::update(State & state) +{ + state.haveUpdate = true; + updateCV.notify_one(); +} + +std::chrono::milliseconds ProgressBar::draw(State & state) +{ + auto nextWakeup = A_LONG_TIME; + + state.haveUpdate = false; + if (state.paused || !state.active) return nextWakeup; + + std::string line; + + std::string status = getStatus(state); + if (!status.empty()) { + line += '['; + line += status; + line += "]"; } - std::chrono::milliseconds draw(State & state) - { - auto nextWakeup = A_LONG_TIME; + auto now = std::chrono::steady_clock::now(); - state.haveUpdate = false; - if (state.paused || !state.active) return nextWakeup; + if (!state.activities.empty()) { + if (!status.empty()) line += " "; + auto i = state.activities.rbegin(); - std::string line; - - std::string status = getStatus(state); - if (!status.empty()) { - line += '['; - line += status; - line += "]"; - } - - auto now = std::chrono::steady_clock::now(); - - if (!state.activities.empty()) { - if (!status.empty()) line += " "; - auto i = state.activities.rbegin(); - - while (i != state.activities.rend()) { - if (i->visible && (!i->s.empty() || !i->lastLine.empty())) { - /* Don't show activities until some time has - passed, to avoid displaying very short - activities. */ - auto delay = std::chrono::milliseconds(10); - if (i->startTime + delay < now) - break; - else - nextWakeup = std::min(nextWakeup, std::chrono::duration_cast(delay - (now - i->startTime))); - } - ++i; - } - - if (i != state.activities.rend()) { - line += i->s; - if (!i->phase.empty()) { - line += " ("; - line += i->phase; - line += ")"; - } - if (!i->lastLine.empty()) { - if (!i->s.empty()) line += ": "; - line += i->lastLine; - } - } - } - - auto width = getWindowSize().second; - if (width <= 0) width = std::numeric_limits::max(); - - writeToStderr("\r" + filterANSIEscapes(line, false, width) + ANSI_NORMAL + "\e[K"); - - return nextWakeup; - } - - std::string getStatus(State & state) - { - constexpr auto MiB = 1024.0 * 1024.0; - - std::string res; - - auto renderActivity = [&](ActivityType type, const std::string & itemFmt, const std::string & numberFmt = "%d", double unit = 1) { - auto & act = state.activitiesByType[type]; - uint64_t done = act.done, expected = act.done, running = 0, failed = act.failed; - for (auto & [actId, infoIt] : act.its) { - done += infoIt->done; - expected += infoIt->expected; - running += infoIt->running; - failed += infoIt->failed; - } - - expected = std::max(expected, act.expected); - - std::string s; - - if (running || done || expected || failed) { - if (running) - if (expected != 0) - s = fmt(ANSI_BLUE + numberFmt + ANSI_NORMAL "/" ANSI_GREEN + numberFmt + ANSI_NORMAL "/" + numberFmt, - running / unit, done / unit, expected / unit); - else - s = fmt(ANSI_BLUE + numberFmt + ANSI_NORMAL "/" ANSI_GREEN + numberFmt + ANSI_NORMAL, - running / unit, done / unit); - else if (expected != done) - if (expected != 0) - s = fmt(ANSI_GREEN + numberFmt + ANSI_NORMAL "/" + numberFmt, - done / unit, expected / unit); - else - s = fmt(ANSI_GREEN + numberFmt + ANSI_NORMAL, done / unit); + while (i != state.activities.rend()) { + if (i->visible && (!i->s.empty() || !i->lastLine.empty())) { + /* Don't show activities until some time has + passed, to avoid displaying very short + activities. */ + auto delay = std::chrono::milliseconds(10); + if (i->startTime + delay < now) + break; 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); + nextWakeup = std::min(nextWakeup, std::chrono::duration_cast(delay - (now - i->startTime))); } + ++i; + } - return s; - }; + if (i != state.activities.rend()) { + line += i->s; + if (!i->phase.empty()) { + line += " ("; + line += i->phase; + line += ")"; + } + if (!i->lastLine.empty()) { + if (!i->s.empty()) line += ": "; + line += i->lastLine; + } + } + } - auto showActivity = [&](ActivityType type, const std::string & itemFmt, const std::string & numberFmt = "%d", double unit = 1) { - auto s = renderActivity(type, itemFmt, numberFmt, unit); - if (s.empty()) return; + auto width = getWindowSize().second; + if (width <= 0) width = std::numeric_limits::max(); + + writeToStderr("\r" + filterANSIEscapes(line, false, width) + ANSI_NORMAL + "\e[K"); + + return nextWakeup; +} + +std::string ProgressBar::getStatus(State & state) +{ + constexpr auto MiB = 1024.0 * 1024.0; + + std::string res; + + auto renderActivity = [&](ActivityType type, const std::string & itemFmt, const std::string & numberFmt = "%d", double unit = 1) { + auto & act = state.activitiesByType[type]; + uint64_t done = act.done, expected = act.done, running = 0, failed = act.failed; + for (auto & [actId, infoIt] : act.its) { + done += infoIt->done; + expected += infoIt->expected; + running += infoIt->running; + failed += infoIt->failed; + } + + expected = std::max(expected, act.expected); + + std::string s; + + if (running || done || expected || failed) { + if (running) + if (expected != 0) + s = fmt(ANSI_BLUE + numberFmt + ANSI_NORMAL "/" ANSI_GREEN + numberFmt + ANSI_NORMAL "/" + numberFmt, + running / unit, done / unit, expected / unit); + else + s = fmt(ANSI_BLUE + numberFmt + ANSI_NORMAL "/" ANSI_GREEN + numberFmt + ANSI_NORMAL, + running / unit, done / unit); + else if (expected != done) + if (expected != 0) + s = fmt(ANSI_GREEN + numberFmt + ANSI_NORMAL "/" + numberFmt, + done / unit, expected / unit); + else + s = fmt(ANSI_GREEN + numberFmt + ANSI_NORMAL, done / 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; + }; + + auto showActivity = [&](ActivityType type, const std::string & itemFmt, const std::string & numberFmt = "%d", double unit = 1) { + auto s = renderActivity(type, itemFmt, numberFmt, unit); + if (s.empty()) return; + if (!res.empty()) res += ", "; + res += s; + }; + + showActivity(actBuilds, "%s built"); + + auto s1 = renderActivity(actCopyPaths, "%s copied"); + 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(actFileTransfer, "%s MiB DL", "%.1f", MiB); + + { + auto s = renderActivity(actOptimiseStore, "%s paths optimised"); + if (s != "") { + s += fmt(", %.1f MiB / %d inodes freed", state.bytesLinked / MiB, state.filesLinked); if (!res.empty()) res += ", "; res += s; - }; - - showActivity(actBuilds, "%s built"); - - auto s1 = renderActivity(actCopyPaths, "%s copied"); - 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(actFileTransfer, "%s MiB DL", "%.1f", MiB); - - { - auto s = renderActivity(actOptimiseStore, "%s paths optimised"); - if (s != "") { - s += fmt(", %.1f MiB / %d inodes freed", state.bytesLinked / MiB, state.filesLinked); - if (!res.empty()) res += ", "; - res += s; - } - } - - // FIXME: don't show "done" paths in green. - showActivity(actVerifyPaths, "%s paths verified"); - - if (state.corruptedPaths) { - if (!res.empty()) res += ", "; - res += fmt(ANSI_RED "%d corrupted" ANSI_NORMAL, state.corruptedPaths); - } - - if (state.untrustedPaths) { - if (!res.empty()) res += ", "; - res += fmt(ANSI_RED "%d untrusted" ANSI_NORMAL, state.untrustedPaths); - } - - return res; - } - - void writeToStdout(std::string_view s) override - { - auto state(state_.lock()); - if (state->active) { - std::cerr << "\r\e[K"; - Logger::writeToStdout(s); - draw(*state); - } else { - Logger::writeToStdout(s); } } - std::optional ask(std::string_view msg) override - { - auto state(state_.lock()); - if (!state->active || !isatty(STDIN_FILENO)) return {}; - std::cerr << fmt("\r\e[K%s ", msg); - auto s = trim(readLine(STDIN_FILENO)); - if (s.size() != 1) return {}; + // FIXME: don't show "done" paths in green. + showActivity(actVerifyPaths, "%s paths verified"); + + if (state.corruptedPaths) { + if (!res.empty()) res += ", "; + res += fmt(ANSI_RED "%d corrupted" ANSI_NORMAL, state.corruptedPaths); + } + + if (state.untrustedPaths) { + if (!res.empty()) res += ", "; + res += fmt(ANSI_RED "%d untrusted" ANSI_NORMAL, state.untrustedPaths); + } + + return res; +} + +void ProgressBar::writeToStdout(std::string_view s) +{ + auto state(state_.lock()); + if (state->active) { + std::cerr << "\r\e[K"; + Logger::writeToStdout(s); draw(*state); - return s[0]; + } else { + Logger::writeToStdout(s); } +} - void setPrintBuildLogs(bool printBuildLogs) override - { - this->printBuildLogs = printBuildLogs; - } -}; +std::optional ProgressBar::ask(std::string_view msg) +{ + auto state(state_.lock()); + if (!state->active || !isatty(STDIN_FILENO)) return {}; + std::cerr << fmt("\r\e[K%s ", msg); + auto s = trim(readLine(STDIN_FILENO)); + if (s.size() != 1) return {}; + draw(*state); + return s[0]; +} + +void ProgressBar::setPrintBuildLogs(bool printBuildLogs) +{ + this->printBuildLogs = printBuildLogs; +} Logger * makeProgressBar() { diff --git a/src/libmain/progress-bar.hh b/src/libmain/progress-bar.hh index c3c6e3833..ae6e0d6da 100644 --- a/src/libmain/progress-bar.hh +++ b/src/libmain/progress-bar.hh @@ -1,10 +1,131 @@ #pragma once ///@file +#include + #include "logging.hh" +#include "sync.hh" namespace nix { +// 100 years ought to be enough for anyone (yet sufficiently smaller than max() to not cause signed integer overflow). +constexpr const auto A_LONG_TIME = std::chrono::duration_cast( + 100 * 365 * std::chrono::seconds(86400) +); + +class ProgressBar : public Logger +{ +private: + struct ActInfo + { + std::string s, lastLine, phase; + ActivityType type = actUnknown; + uint64_t done = 0; + uint64_t expected = 0; + uint64_t running = 0; + uint64_t failed = 0; + std::map expectedByType; + bool visible = true; + ActivityId parent; + std::optional name; + std::chrono::time_point startTime; + }; + + struct ActivitiesByType + { + std::map::iterator> its; + uint64_t done = 0; + uint64_t expected = 0; + uint64_t failed = 0; + }; + + struct State + { + std::list activities; + std::map::iterator> its; + + std::map activitiesByType; + + uint64_t filesLinked = 0, bytesLinked = 0; + + uint64_t corruptedPaths = 0, untrustedPaths = 0; + + bool active = true; + bool paused = false; + bool haveUpdate = true; + }; + + Sync state_; + + std::thread updateThread; + + std::condition_variable quitCV, updateCV; + + bool printBuildLogs = false; + bool isTTY; + +public: + + ProgressBar(bool isTTY) + : isTTY(isTTY) + { + state_.lock()->active = isTTY; + updateThread = std::thread([&]() { + auto state(state_.lock()); + auto nextWakeup = A_LONG_TIME; + while (state->active) { + if (!state->haveUpdate) + state.wait_for(updateCV, nextWakeup); + nextWakeup = draw(*state); + state.wait_for(quitCV, std::chrono::milliseconds(50)); + } + }); + } + + ~ProgressBar(); + + void stop() override final; + + void pause() override; + + void resume() override; + + bool isVerbose() override; + + void log(Verbosity lvl, std::string_view s) override; + + void logEI(const ErrorInfo & ei) override; + + void log(State & state, Verbosity lvl, std::string_view s); + + void startActivity( + ActivityId act, + Verbosity lvl, + ActivityType type, + const std::string & s, + const Fields & fields, + ActivityId parent + ) override; + + bool hasAncestor(State & state, ActivityType type, ActivityId act); + + void stopActivity(ActivityId act) override; + + void result(ActivityId act, ResultType type, const std::vector & fields) override; + + void update(State & state); + + std::chrono::milliseconds draw(State & state); + + std::string getStatus(State & state); + + void writeToStdout(std::string_view s) override; + + std::optional ask(std::string_view msg) override; + + void setPrintBuildLogs(bool printBuildLogs) override; +}; + Logger * makeProgressBar(); void startProgressBar(); From c93129761dc022cfe1bd8751f9935ccfd1b78759 Mon Sep 17 00:00:00 2001 From: Qyriad Date: Wed, 19 Jun 2024 22:11:25 -0600 Subject: [PATCH 3/4] use a type alias for ProgressBar's chosen time point type Change-Id: I621a455b1daba806fc498958aee7931fbfc55445 --- src/libmain/progress-bar.hh | 4 +++- 1 file changed, 3 insertions(+), 1 deletion(-) diff --git a/src/libmain/progress-bar.hh b/src/libmain/progress-bar.hh index ae6e0d6da..1ac7ba97b 100644 --- a/src/libmain/progress-bar.hh +++ b/src/libmain/progress-bar.hh @@ -18,6 +18,8 @@ class ProgressBar : public Logger private: struct ActInfo { + using TimePoint = std::chrono::time_point; + std::string s, lastLine, phase; ActivityType type = actUnknown; uint64_t done = 0; @@ -28,7 +30,7 @@ private: bool visible = true; ActivityId parent; std::optional name; - std::chrono::time_point startTime; + TimePoint startTime; }; struct ActivitiesByType From 252192bb4385e09a420feb9e4a8f8b0ea5741da6 Mon Sep 17 00:00:00 2001 From: Qyriad Date: Wed, 19 Jun 2024 22:12:24 -0600 Subject: [PATCH 4/4] add a basic libmain test for the progress bar rendering Hooray for leaky abstraction allowing us to test this particular part of the render pipeline. Change-Id: Ie0f251ff874f63324e6a9c6388b84ec6507eeae2 --- src/libmain/progress-bar.hh | 5 +--- tests/unit/libmain/progress-bar.cc | 43 ++++++++++++++++++++++++++++++ tests/unit/meson.build | 22 +++++++++++++++ 3 files changed, 66 insertions(+), 4 deletions(-) create mode 100644 tests/unit/libmain/progress-bar.cc diff --git a/src/libmain/progress-bar.hh b/src/libmain/progress-bar.hh index 1ac7ba97b..76e2ed4ff 100644 --- a/src/libmain/progress-bar.hh +++ b/src/libmain/progress-bar.hh @@ -13,9 +13,8 @@ constexpr const auto A_LONG_TIME = std::chrono::duration_cast; @@ -66,8 +65,6 @@ private: bool printBuildLogs = false; bool isTTY; -public: - ProgressBar(bool isTTY) : isTTY(isTTY) { diff --git a/tests/unit/libmain/progress-bar.cc b/tests/unit/libmain/progress-bar.cc new file mode 100644 index 000000000..34a87dd9d --- /dev/null +++ b/tests/unit/libmain/progress-bar.cc @@ -0,0 +1,43 @@ +#include + +#include "eval.hh" +#include "progress-bar.hh" +#include "logging.hh" +#include "shared.hh" + +constexpr std::string_view TEST_URL = "https://github.com/NixOS/nixpkgs/archive/master.tar.gz"; +// Arbitrary number. We picked the size of a Nixpkgs tarball that we downloaded. +constexpr uint64_t TEST_EXPECTED = 43'370'307; +// Arbitrary number. We picked the progress made on a Nixpkgs tarball download we interrupted. +constexpr uint64_t TEST_DONE = 1'787'251; + +constexpr std::string_view EXPECTED = ANSI_GREEN "1.7" ANSI_NORMAL "/41.4 MiB DL"; +// Mostly here for informational purposes, but also if we change the way the escape codes +// are defined this test might break in some annoying to debug way. +constexpr std::string_view EXPECTED_RAW = "\x1b[32;1m1.7\x1b[0m/41.4 MiB DL"; +static_assert(EXPECTED == EXPECTED_RAW, "Hey, hey, the ANSI escape code definitions prolly changed"); + +namespace nix +{ + TEST(ProgressBar, basicStatusRender) { + initNix(); + initGC(); + + startProgressBar(); + ASSERT_NE(dynamic_cast(logger), nullptr); + ProgressBar & progressBar = *dynamic_cast(logger); + + Activity act( + progressBar, + lvlDebug, + actFileTransfer, + fmt("downloading '%s'", TEST_URL), + { "https://github.com/NixOS/nixpkgs/archive/master.tar.gz" } + ); + act.progress(TEST_DONE, TEST_EXPECTED); + auto state = progressBar.state_.lock(); + std::string const autoStatus = progressBar.getStatus(*state); + + ASSERT_EQ(autoStatus, EXPECTED); + } +} diff --git a/tests/unit/meson.build b/tests/unit/meson.build index c3eefeede..9f19e5fd9 100644 --- a/tests/unit/meson.build +++ b/tests/unit/meson.build @@ -249,3 +249,25 @@ test( suite : 'check', protocol : 'gtest', ) + +libmain_tester = executable( + 'liblixmain-tests', + files('libmain/progress-bar.cc'), + dependencies : [ + liblixmain, + liblixexpr, + liblixutil, + liblixstore, + gtest, + boost, + ], + cpp_pch : cpp_pch, +) + +test( + 'libmain-unit-tests', + libmain_tester, + args : tests_args, + suite : 'check', + protocol : 'gtest', +)