Merge branch '1.12.1/still-running' into 1.12.1/continental

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<Edge*> 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<const Subprocess*, Edge*>::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();
@@ -1044,6 +1064,28 @@ bool Builder::FinishCommand(CommandRunner::Result* result, string* err) {
   return true;
 }
 
+void Builder::ReportProgress(void)
+{
+  vector<Edge*> 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,

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<Edge*> GetActiveEdges() { return std::vector<Edge*>(); }
   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);

src/exit_status.h

@@ -18,7 +18,8 @@
 enum ExitStatus {
   ExitSuccess,
   ExitFailure,
-  ExitInterrupted
+  ExitInterrupted,
+  ExitTimeout
 };
 
 #endif  // NINJA_EXIT_STATUS_H_

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');
+}

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);

src/status.cc

@@ -31,14 +31,15 @@
 #include <io.h>
 #endif
 
+#include <assert.h>
 #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

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_;
 

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();

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_

src/version.cc

@@ -20,7 +20,7 @@
 
 using namespace std;
 
-const char* kNinjaVersion = "1.12.1.conti.1";
+const char* kNinjaVersion = "1.12.1.conti.2";
 
 void ParseVersion(const string& version, int* major, int* minor) {
   size_t end = version.find('.');