Update status periodically in smart terminals

doc/manual.asciidoc

@@ -190,7 +190,8 @@ you don't need to pass `-j`.)
 Environment variables
 ~~~~~~~~~~~~~~~~~~~~~
 
-Ninja supports one environment variable to control its behavior:
+Ninja supports a few environment variables to control its behavior:
+
 `NINJA_STATUS`, the progress status printed before the rule being run.
 
 Several placeholders are available:
@@ -215,6 +216,12 @@ The default progress status is `"[%f/%t] "` (note the trailing space
 to separate from the build rule). Another example of possible progress status
 could be `"[%u/%r/%f] "`.
 
+`NINJA_STATUS_REFRESH_MILLIS`, the refresh timeout in milliseconds
+for status updates in interactive terminals. The default value is 1000,
+to allow time-sensitive formatters like `%w` to be updated during
+long build runs (e.g. when one or more build commands run for a long
+time).
+
 Extra tools
 ~~~~~~~~~~~
 

misc/output_test.py

@@ -16,6 +16,7 @@
 
 default_env = dict(os.environ)
 default_env.pop('NINJA_STATUS', None)
+default_env.pop('NINJA_STATUS_REFRESH_MILLIS', None)
 default_env.pop('CLICOLOR_FORCE', None)
 default_env['TERM'] = ''
 NINJA_PATH = os.path.abspath('./ninja')
@@ -310,6 +311,41 @@ def test_ninja_status_quiet(self) -> None:
         output = run(Output.BUILD_SIMPLE_ECHO, flags='--quiet')
         self.assertEqual(output, 'do thing\n')
 
+    @unittest.skip("Time-based test fails on Github CI")
+    def test_ninja_status_periodic_update(self) -> None:
+        b =  BuildDir('''\
+           rule sleep_then_print
+             command = sleep 2 && echo done
+             description = sleep2s
+
+           build all: sleep_then_print
+           ''')
+        with b:
+          env = default_env.copy()
+          env["NINJA_STATUS"] = "[%w] "
+          self.assertListEqual(
+            b.run('all', raw_output=True, env=env).replace("\r\n", "<CRLF>").split("\r"),
+            [
+              "",
+              "[00:00] sleep2s\x1b[K",
+              "[00:01] sleep2s\x1b[K",
+              "[00:02] sleep2s\x1b[K",
+              "[00:02] sleep2s\x1b[K<CRLF>done<CRLF>",
+            ])
+
+          env["NINJA_STATUS_REFRESH_MILLIS"] = "500"
+          self.assertListEqual(
+            b.run('all', raw_output=True, env=env).replace("\r\n", "<CRLF>").split("\r"),
+            [
+              "",
+              "[00:00] sleep2s\x1b[K",
+              "[00:00] sleep2s\x1b[K",
+              "[00:01] sleep2s\x1b[K",
+              "[00:01] sleep2s\x1b[K",
+              "[00:02] sleep2s\x1b[K",
+              "[00:02] sleep2s\x1b[K<CRLF>done<CRLF>",
+            ])
+
     def test_entering_directory_on_stdout(self) -> None:
         output = run(Output.BUILD_SIMPLE_ECHO, flags='-C$PWD', pipe=True)
         self.assertEqual(output.splitlines()[0][:25], "ninja: Entering directory")

src/build.cc

@@ -696,10 +696,13 @@ bool Builder::Build(string* err) {
 
   // Set up the command runner if we haven't done so already.
   if (!command_runner_.get()) {
-    if (config_.dry_run)
+    if (config_.dry_run) {
       command_runner_.reset(new DryRunCommandRunner);
-    else
-      command_runner_.reset(CommandRunner::factory(config_));
+    } else {
+      command_runner_.reset(CommandRunner::factory(config_, [this]() {
+        status_->Refresh(GetTimeMillis() - start_time_millis_);
+      }));
+    }
   }
 
   // We are about to start the build process.

src/build.h

@@ -16,6 +16,7 @@
 #define NINJA_BUILD_H_
 
 #include <cstdio>
+#include <functional>
 #include <map>
 #include <memory>
 #include <string>
@@ -151,6 +152,9 @@ struct CommandRunner {
   virtual size_t CanRunMore() const = 0;
   virtual bool StartCommand(Edge* edge) = 0;
 
+  // A callable value used to refresh the current Ninja status.
+  using StatusRefresher = std::function<void(void)>;
+
   /// The result of waiting for a command.
   struct Result {
     Result() : edge(NULL) {}
@@ -166,27 +170,30 @@ struct CommandRunner {
   virtual void Abort() {}
 
   /// Creates the RealCommandRunner
-  static CommandRunner* factory(const BuildConfig& config);
+  static CommandRunner* factory(const BuildConfig& config,
+                                StatusRefresher&& refresh_status);
 };
 
 /// Options (e.g. verbosity, parallelism) passed to a build.
 struct BuildConfig {
-  BuildConfig() : verbosity(NORMAL), dry_run(false), parallelism(1),
-                  failures_allowed(1), max_load_average(-0.0f) {}
+  BuildConfig() = default;
 
   enum Verbosity {
     QUIET,  // No output -- used when testing.
     NO_STATUS_UPDATE,  // just regular output but suppress status update
     NORMAL,  // regular output and status update
     VERBOSE
   };
-  Verbosity verbosity;
-  bool dry_run;
-  int parallelism;
-  int failures_allowed;
+  Verbosity verbosity = NORMAL;
+  bool dry_run = false;
+  int parallelism = 1;
+  int failures_allowed = 1;
   /// The maximum load average we must not exceed. A negative value
   /// means that we do not have any limit.
-  double max_load_average;
+  double max_load_average = -0.0f;
+  /// Number of milliseconds between status refreshes in interactive
+  /// terminals.
+  int status_refresh_millis = 1000;
   DepfileParserOptions depfile_parser_options;
 };
 

src/ninja.cc

@@ -1729,6 +1729,11 @@ NORETURN void real_main(int argc, char** argv) {
   Options options = {};
   options.input_file = "build.ninja";
 
+  const char* status_refresh_env = getenv("NINJA_STATUS_REFRESH_MILLIS");
+  if (status_refresh_env) {
+    config.status_refresh_millis = atoi(status_refresh_env);
+  }
+
   setvbuf(stdout, NULL, _IOLBF, BUFSIZ);
   const char* ninja_command = argv[0];
 

src/real_command_runner.cc

@@ -16,14 +16,17 @@
 #include "subprocess.h"
 
 struct RealCommandRunner : public CommandRunner {
-  explicit RealCommandRunner(const BuildConfig& config) : config_(config) {}
+  explicit RealCommandRunner(const BuildConfig& config,
+                             StatusRefresher&& refresh_status)
+      : config_(config), refresh_status_(std::move(refresh_status)) {}
   size_t CanRunMore() const override;
   bool StartCommand(Edge* edge) override;
   bool WaitForCommand(Result* result) override;
   std::vector<Edge*> GetActiveEdges() override;
   void Abort() override;
 
   const BuildConfig& config_;
+  StatusRefresher refresh_status_;
   SubprocessSet subprocs_;
   std::map<const Subprocess*, Edge*> subproc_to_edge_;
 };
@@ -75,9 +78,14 @@ bool RealCommandRunner::StartCommand(Edge* edge) {
 
 bool RealCommandRunner::WaitForCommand(Result* result) {
   Subprocess* subproc;
-  while ((subproc = subprocs_.NextFinished()) == NULL) {
-    bool interrupted = subprocs_.DoWork();
-    if (interrupted)
+  while ((subproc = subprocs_.NextFinished()) == nullptr) {
+    SubprocessSet::WorkResult ret =
+        subprocs_.DoWork(config_.status_refresh_millis);
+    if (ret == SubprocessSet::WorkResult::TIMEOUT) {
+      refresh_status_();
+      continue;
+    }
+    if (ret == SubprocessSet::WorkResult::INTERRUPTION)
       return false;
   }
 
@@ -93,6 +101,7 @@ bool RealCommandRunner::WaitForCommand(Result* result) {
   return true;
 }
 
-CommandRunner* CommandRunner::factory(const BuildConfig& config) {
-  return new RealCommandRunner(config);
+CommandRunner* CommandRunner::factory(const BuildConfig& config,
+                                      StatusRefresher&& refresh_status) {
+  return new RealCommandRunner(config, std::move(refresh_status));
 }

src/status.h

@@ -34,6 +34,13 @@ struct Status {
   virtual void BuildStarted() = 0;
   virtual void BuildFinished() = 0;
 
+  /// Refresh status display after some time has passed.  Useful
+  /// when printing the status on an interactive terminal. Does
+  /// nothing by default. \arg cur_time_millis is the current time
+  /// expressed in milliseconds, using the same epoch than the
+  /// one used in BuildEdgeStart() and BuildEdgeFinished().
+  virtual void Refresh(int64_t cur_time_millis) {}
+
   /// Set the Explanations instance to use to report explanations,
   /// argument can be nullptr if no explanations need to be printed
   /// (which is the default).

src/status_printer.cc

@@ -304,13 +304,13 @@ string StatusPrinter::FormatProgressStatus(const char* progress_status_format,
 
         // Overall finished edges per second.
       case 'o':
-        SnprintfRate(finished_edges_ / (time_millis_ / 1e3), buf, "%.1f");
+        SnprintfRate(finished_edges_ / (time_millis / 1e3), buf, "%.1f");
         out += buf;
         break;
 
         // Current rate, average over the last '-j' jobs.
       case 'c':
-        current_rate_.UpdateRate(finished_edges_, time_millis_);
+        current_rate_.UpdateRate(finished_edges_, time_millis);
         SnprintfRate(current_rate_.rate(), buf, "%.1f");
         out += buf;
         break;
@@ -336,15 +336,15 @@ string StatusPrinter::FormatProgressStatus(const char* progress_status_format,
       case 'E':  // ETA, seconds
       case 'W':  // ETA, human-readable
       {
-        double elapsed_sec = time_millis_ / 1e3;
+        double elapsed_sec = time_millis / 1e3;
         double eta_sec = -1;  // To be printed as "?".
         if (time_predicted_percentage_ != 0.0) {
-          // So, we know that we've spent time_millis_ wall clock,
+          // So, we know that we've spent time_millis wall clock,
           // and that is time_predicted_percentage_ percent.
           // How much time will we need to complete 100%?
-          double total_wall_time = time_millis_ / time_predicted_percentage_;
+          double total_wall_time = time_millis / time_predicted_percentage_;
           // Naturally, that gives us the time remaining.
-          eta_sec = (total_wall_time - time_millis_) / 1e3;
+          eta_sec = (total_wall_time - time_millis) / 1e3;
         }
 
         const bool print_with_hours =
@@ -428,17 +428,28 @@ void StatusPrinter::PrintStatus(const Edge* edge, int64_t time_millis) {
 
   bool force_full_command = config_.verbosity == BuildConfig::VERBOSE;
 
-  string to_print = edge->GetBinding("description");
-  if (to_print.empty() || force_full_command)
-    to_print = edge->GetBinding("command");
+  last_description_ = edge->GetBinding("description");
+  if (last_description_.empty() || force_full_command)
+    last_description_ = edge->GetBinding("command");
 
-  to_print = FormatProgressStatus(progress_status_format_, time_millis)
-      + to_print;
+  RefreshStatus(time_millis, force_full_command);
+}
 
+void StatusPrinter::RefreshStatus(int64_t cur_time_millis,
+                                  bool force_full_command) {
+  std::string to_print =
+      FormatProgressStatus(progress_status_format_, cur_time_millis) +
+      last_description_;
   printer_.Print(to_print,
                  force_full_command ? LinePrinter::FULL : LinePrinter::ELIDE);
 }
 
+void StatusPrinter::Refresh(int64_t cur_time_millis) {
+  if (printer_.is_smart_terminal()) {
+    RefreshStatus(cur_time_millis, false);
+  }
+}
+
 void StatusPrinter::Warning(const char* msg, ...) {
   va_list ap;
   va_start(ap, msg);

src/status_printer.h

@@ -36,6 +36,8 @@ struct StatusPrinter : Status {
   void BuildStarted() override;
   void BuildFinished() override;
 
+  void Refresh(int64_t cur_time_millis) override;
+
   void Info(const char* msg, ...) override;
   void Warning(const char* msg, ...) override;
   void Error(const char* msg, ...) override;
@@ -82,6 +84,8 @@ struct StatusPrinter : Status {
   /// For how many edges we don't know the previous run time?
   int eta_unpredictable_edges_remaining_ = 0;
 
+  void RefreshStatus(int64_t cur_time_millis, bool force_full_command);
+
   void RecalculateProgressPrediction();
 
   /// Prints progress output.
@@ -93,6 +97,9 @@ struct StatusPrinter : Status {
   /// The custom progress status format to use.
   const char* progress_status_format_;
 
+  /// Last command's description or command-line.
+  std::string last_description_;
+
   template <size_t S>
   void SnprintfRate(double rate, char (&buf)[S], const char* format) const {
     if (rate == -1)