From 09239218e46da8b57febd565e7e44da5fcfc936f Mon Sep 17 00:00:00 2001 From: Daniel Weber Date: Mon, 16 Sep 2024 09:34:31 +0200 Subject: [PATCH] Emitting output of commands running solo in real time Printing 'still-running' spinner for long-running commands --- src/build.cc | 42 +++++++++++++++++++++++ src/build.h | 13 +++++++ src/exit_status.h | 3 +- src/line_printer.cc | 8 +++++ src/line_printer.h | 4 +++ src/status.cc | 76 ++++++++++++++++++++++++++++++++++++++--- src/status.h | 12 +++++++ src/subprocess-posix.cc | 12 +++++-- src/subprocess.h | 5 +++ src/version.cc | 2 +- 10 files changed, 169 insertions(+), 8 deletions(-) diff --git a/src/build.cc b/src/build.cc index 36b52dc188..d58afd83a2 100644 --- a/src/build.cc +++ b/src/build.cc @@ -36,6 +36,7 @@ #include "disk_interface.h" #include "graph.h" #include "metrics.h" +#include "msvc_helper.h" #include "state.h" #include "status.h" #include "subprocess.h" @@ -600,6 +601,7 @@ struct RealCommandRunner : public CommandRunner { virtual size_t CanRunMore() const; virtual bool StartCommand(Edge* edge); virtual bool WaitForCommand(Result* result); + virtual void PeekCommandOutput(Edge* edge, string* out); virtual vector GetActiveEdges(); virtual void Abort(); @@ -642,6 +644,16 @@ size_t RealCommandRunner::CanRunMore() const { return capacity; } +void RealCommandRunner::PeekCommandOutput(Edge* edge, string* out) +{ + // Note: search linearly, but as long this is only invoked when number of + // edges == 1, nothing better is necessary. + for (map::iterator i = subproc_to_edge_.begin(); + i != subproc_to_edge_.end(); ++i) + if (i->second == edge) + *out = i->first->GetOutput(); +} + bool RealCommandRunner::StartCommand(Edge* edge) { string command = edge->EvaluateCommand(); Subprocess* subproc = subprocs_.Add(command, edge->use_console()); @@ -658,6 +670,9 @@ bool RealCommandRunner::WaitForCommand(Result* result) { bool interrupted = subprocs_.DoWork(); if (interrupted) return false; + + result->status = ExitTimeout; + return true; } result->status = subproc->Finish(); @@ -841,6 +856,11 @@ bool Builder::Build(string* err) { return false; } + if (result.status == ExitTimeout) { + ReportProgress(); + continue; + } + --pending_commands; if (!FinishCommand(&result, err)) { Cleanup(); @@ -1030,6 +1050,28 @@ bool Builder::FinishCommand(CommandRunner::Result* result, string* err) { return true; } +void Builder::ReportProgress(void) +{ + vector active_edges = command_runner_->GetActiveEdges(); + if (active_edges.size() < 1) + return; + + Edge* edge = active_edges[0]; + if (active_edges.size() == 1 && !plan_.HasWork()) { + // If a command is running 'solo' AND produces some output, start printing + // its output in the real time w/o waiting for its completion. + string output; + command_runner_->PeekCommandOutput(edge, &output); + if (output.size()) { + ((StatusPrinter*)status_)->BuildEdgeRunningSolo(edge, output); + return; + } + } + + //Call this only if it is needed to have feedback that a long command is under execution + //((StatusPrinter*)status_)->BuildEdgeStillRunning(edge); +} + bool Builder::ExtractDeps(CommandRunner::Result* result, const string& deps_type, const string& deps_prefix, diff --git a/src/build.h b/src/build.h index 471f0b2caa..e9c6beb815 100644 --- a/src/build.h +++ b/src/build.h @@ -25,6 +25,8 @@ #include "graph.h" #include "exit_status.h" #include "util.h" // int64_t +#include "line_printer.h" +#include "metrics.h" struct BuildLog; struct Builder; @@ -34,6 +36,9 @@ struct Node; struct State; struct Status; +const uint64_t kStillRunningDelayMsec = 3000; +const int kStillRunningFPS = 4; + /// Plan stores the state of a build plan: what we intend to build, /// which steps we're ready to execute. struct Plan { @@ -48,6 +53,9 @@ struct Plan { // Returns NULL if there's no work to do. Edge* FindWork(); + // Returns true if there are edges waiting to run now. + bool HasWork() const { return !ready_.empty(); } + /// Returns true if there's more work to be done. bool more_to_do() const { return wanted_edges_ > 0 && command_edges_ > 0; } @@ -159,6 +167,9 @@ struct CommandRunner { /// Wait for a command to complete, or return false if interrupted. virtual bool WaitForCommand(Result* result) = 0; + /// Return command output collected so far + virtual void PeekCommandOutput(Edge* edge, std::string* out) {} + virtual std::vector GetActiveEdges() { return std::vector(); } virtual void Abort() {} }; @@ -214,6 +225,8 @@ struct Builder { /// @return false if the build can not proceed further due to a fatal error. bool FinishCommand(CommandRunner::Result* result, std::string* err); + void ReportProgress(void); + /// Used for tests. void SetBuildLog(BuildLog* log) { scan_.set_build_log(log); diff --git a/src/exit_status.h b/src/exit_status.h index a714ece791..12b22c6da0 100644 --- a/src/exit_status.h +++ b/src/exit_status.h @@ -18,7 +18,8 @@ enum ExitStatus { ExitSuccess, ExitFailure, - ExitInterrupted + ExitInterrupted, + ExitTimeout }; #endif // NINJA_EXIT_STATUS_H_ diff --git a/src/line_printer.cc b/src/line_printer.cc index 12e82b3f80..ab3a1ec3af 100644 --- a/src/line_printer.cc +++ b/src/line_printer.cc @@ -165,3 +165,11 @@ void LinePrinter::SetConsoleLocked(bool locked) { line_buffer_.clear(); } } + +void LinePrinter::PrintRaw(const string& to_print) { + if (to_print.empty()) + return; + fwrite(to_print.c_str(), to_print.size(), 1, stdout); + fflush(stdout); + have_blank_line_ = (*to_print.rbegin() == '\n'); +} diff --git a/src/line_printer.h b/src/line_printer.h index a8ec9ff40e..86348363e0 100644 --- a/src/line_printer.h +++ b/src/line_printer.h @@ -39,6 +39,10 @@ struct LinePrinter { /// Prints a string on a new line, not overprinting previous output. void PrintOnNewLine(const std::string& to_print); + /// Prints the string at current cursor position as-is, not overprinting + /// previous output and flushes the stdout. + void PrintRaw(const std::string& to_print); + /// Lock or unlock the console. Any output sent to the LinePrinter while the /// console is locked will not be printed until it is unlocked. void SetConsoleLocked(bool locked); diff --git a/src/status.cc b/src/status.cc index 06f3c20aae..75e008002c 100644 --- a/src/status.cc +++ b/src/status.cc @@ -31,14 +31,15 @@ #include #endif +#include #include "debug_flags.h" using namespace std; StatusPrinter::StatusPrinter(const BuildConfig& config) : config_(config), started_edges_(0), finished_edges_(0), total_edges_(0), - running_edges_(0), progress_status_format_(NULL), - current_rate_(config.parallelism) { + running_edges_(0), next_progress_update_at_(0), solo_bytes_printed_(0), + progress_status_format_(NULL), current_rate_(config.parallelism) { // Don't do anything fancy in verbose mode. if (config_.verbosity != BuildConfig::NORMAL) printer_.set_smart_terminal(false); @@ -85,6 +86,10 @@ void StatusPrinter::BuildEdgeStarted(const Edge* edge, if (edge->use_console() || printer_.is_smart_terminal()) PrintStatus(edge, start_time_millis); + // Edge running solo is supposed to keep running alone. + assert(solo_bytes_printed_ == 0); + RestartStillRunningDelay(); + if (edge->use_console()) printer_.SetConsoleLocked(true); } @@ -172,7 +177,7 @@ void StatusPrinter::BuildEdgeFinished(Edge* edge, int64_t start_time_millis, int64_t end_time_millis, bool success, const string& output) { time_millis_ = end_time_millis; - ++finished_edges_; + int64_t elapsed = end_time_millis - start_time_millis; cpu_time_millis_ += elapsed; @@ -191,6 +196,16 @@ void StatusPrinter::BuildEdgeFinished(Edge* edge, int64_t start_time_millis, if (config_.verbosity == BuildConfig::QUIET) return; + RestartStillRunningDelay(); + if (solo_bytes_printed_ > 0) { + // Special treatment to edges status + BuildEdgeFinishedSolo(edge, success, output); + return; + } + else{ + ++finished_edges_; + } + if (!edge->use_console()) PrintStatus(edge, end_time_millis); @@ -208,7 +223,6 @@ void StatusPrinter::BuildEdgeFinished(Edge* edge, int64_t start_time_millis, } else { printer_.PrintOnNewLine("FAILED: " + outputs + "\n"); } - printer_.PrintOnNewLine(edge->EvaluateCommand() + "\n"); } if (!output.empty()) { @@ -242,6 +256,60 @@ void StatusPrinter::BuildEdgeFinished(Edge* edge, int64_t start_time_millis, } } +void StatusPrinter::BuildEdgeStillRunning(Edge* edge) +{ + if (config_.verbosity == BuildConfig::QUIET) + return; + + int64_t now = GetTimeMillis(); + if (next_progress_update_at_ > now) + return; + + static int ctr = 0; + char status[32]; + snprintf(status, sizeof(status), " (still running.. %c)", "/-\\|"[ctr++ % 4]); + + PrintStatus(edge, now); + next_progress_update_at_ = now + 1000/kStillRunningFPS; +} + +void StatusPrinter::RestartStillRunningDelay() +{ + next_progress_update_at_ = GetTimeMillis() + kStillRunningDelayMsec; +} + +void StatusPrinter::BuildEdgeRunningSolo(Edge* edge, const string& output) +{ + if (config_.verbosity == BuildConfig::QUIET) + return; + + if (output.size() > solo_bytes_printed_) { + if (solo_bytes_printed_ == 0) { + // Print edge description before starting to print its output + ++finished_edges_; + PrintStatus(edge, GetTimeMillis()); + printer_.PrintOnNewLine(""); + } + + printer_.PrintRaw(output.substr(solo_bytes_printed_)); + solo_bytes_printed_ = output.size(); + } +} + +void StatusPrinter::BuildEdgeFinishedSolo(Edge* edge, + bool success, + const string& output) +{ + // Print reminders of the output, if any + BuildEdgeRunningSolo(edge, output); + + // Print the command that has failed + if (!success) + printer_.PrintOnNewLine("^^FAILED: " + edge->EvaluateCommand() + "\n"); + + solo_bytes_printed_ = 0; +} + void StatusPrinter::BuildLoadDyndeps() { // The DependencyScan calls EXPLAIN() to print lines explaining why // it considers a portion of the graph to be out of date. Normally diff --git a/src/status.h b/src/status.h index a1a8fddeae..4a8a71c026 100644 --- a/src/status.h +++ b/src/status.h @@ -55,6 +55,8 @@ struct StatusPrinter : Status { virtual void BuildEdgeFinished(Edge* edge, int64_t start_time_millis, int64_t end_time_millis, bool success, const std::string& output); + virtual void BuildEdgeStillRunning(Edge* edge); + virtual void BuildEdgeRunningSolo(Edge* edge, const std::string& output); virtual void BuildLoadDyndeps(); virtual void BuildStarted(); virtual void BuildFinished(); @@ -75,6 +77,8 @@ struct StatusPrinter : Status { private: void PrintStatus(const Edge* edge, int64_t time_millis); + void RestartStillRunningDelay(); + void BuildEdgeFinishedSolo(Edge* edge, bool success, const std::string& output); const BuildConfig& config_; @@ -107,6 +111,14 @@ struct StatusPrinter : Status { /// Prints progress output. LinePrinter printer_; + /// Timestamp when the next frame with the 'still running' spinner should be + /// displayed. Reset when regular edge start/end notifications are printed. + int64_t next_progress_update_at_; + + /// Counts how much was printed so far for an edge running solo. + /// Non-zero means that only one edge can be running. + size_t solo_bytes_printed_; + /// The custom progress status format to use. const char* progress_status_format_; diff --git a/src/subprocess-posix.cc b/src/subprocess-posix.cc index 8e785406c9..bbe0fefd84 100644 --- a/src/subprocess-posix.cc +++ b/src/subprocess-posix.cc @@ -264,13 +264,17 @@ bool SubprocessSet::DoWork() { } interrupted_ = 0; - int ret = ppoll(&fds.front(), nfds, NULL, &old_mask_); + struct timespec timeout = { 0L, kPollTimeoutNano }; + int ret = ppoll(&fds.front(), nfds, &timeout, &old_mask_); if (ret == -1) { if (errno != EINTR) { perror("ninja: ppoll"); return false; } return IsInterrupted(); + }else if (ret == 0) { + // Timeout + return false; } HandlePendingInterruption(); @@ -315,13 +319,17 @@ bool SubprocessSet::DoWork() { } interrupted_ = 0; - int ret = pselect(nfds, &set, 0, 0, 0, &old_mask_); + struct timespec timeout = { 0L, kPollTimeoutNano }; + int ret = pselect(nfds, &set, 0, 0, &timeout, &old_mask_); if (ret == -1) { if (errno != EINTR) { perror("ninja: pselect"); return false; } return IsInterrupted(); + }else if (ret == 0) { + // Timeout + return false; } HandlePendingInterruption(); diff --git a/src/subprocess.h b/src/subprocess.h index 9e3d2ee98f..82600e652a 100644 --- a/src/subprocess.h +++ b/src/subprocess.h @@ -110,4 +110,9 @@ struct SubprocessSet { #endif }; +/// SubprocessSet::DoWork() may return on a timeout +/// after waiting for kPollTimeoutNano ns, allowing +/// ninja to update progress of long-running tasks. +const long kPollTimeoutNano = 1000000000L/20; // = 20Hz + #endif // NINJA_SUBPROCESS_H_ diff --git a/src/version.cc b/src/version.cc index b19249ff22..f647ad7068 100644 --- a/src/version.cc +++ b/src/version.cc @@ -20,7 +20,7 @@ using namespace std; -const char* kNinjaVersion = "1.12.1"; +const char* kNinjaVersion = "1.12.1.conti.2"; void ParseVersion(const string& version, int* major, int* minor) { size_t end = version.find('.');