Printing 'still-running' spinner for long-running commands

src/build.cc

@@ -75,6 +75,7 @@ BuildStatus::BuildStatus(const BuildConfig& config)
     : config_(config),
       start_time_millis_(GetTimeMillis()),
       started_edges_(0), finished_edges_(0), restarted_edges_(0), total_edges_(0),
+      next_progress_update_at_(0),
       progress_status_format_(NULL),
       overall_rate_(), current_rate_(config.parallelism) {
 
@@ -96,6 +97,8 @@ void BuildStatus::BuildEdgeStarted(Edge* edge) {
   running_edges_.insert(make_pair(edge, start_time));
   ++started_edges_;
 
+  RestartStillRunningDelay();
+
   PrintStatus(edge);
 }
 
@@ -120,6 +123,8 @@ void BuildStatus::BuildEdgeFinished(Edge* edge,
   if (config_.verbosity == BuildConfig::QUIET)
     return;
 
+  RestartStillRunningDelay();
+
   if (printer_.is_smart_terminal())
     PrintStatus(edge);
 
@@ -149,6 +154,28 @@ void BuildStatus::BuildEdgeFinished(Edge* edge,
   }
 }
 
+void BuildStatus::BuildEdgeStillRunning(Edge* edge)
+{
+  if (config_.verbosity == BuildConfig::QUIET || !printer_.is_smart_terminal())
+    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, status);
+  next_progress_update_at_ = now + 1000/kStillRunningFPS;
+}
+
+void BuildStatus::RestartStillRunningDelay()
+{
+  next_progress_update_at_ = GetTimeMillis() + kStillRunningDelayMsec;
+}
+
 void BuildStatus::BuildFinished() {
   printer_.PrintOnNewLine("");
 }
@@ -236,7 +263,7 @@ string BuildStatus::FormatProgressStatus(
   return out;
 }
 
-void BuildStatus::PrintStatus(Edge* edge) {
+void BuildStatus::PrintStatus(Edge* edge, const char* trailer) {
   if (config_.verbosity == BuildConfig::QUIET)
     return;
 
@@ -250,7 +277,7 @@ void BuildStatus::PrintStatus(Edge* edge) {
     overall_rate_.Restart();
     current_rate_.Restart();
   }
-  to_print = FormatProgressStatus(progress_status_format_) + to_print;
+  to_print = FormatProgressStatus(progress_status_format_) + to_print + trailer;
 
   printer_.Print(to_print,
                  force_full_command ? LinePrinter::FULL : LinePrinter::ELIDE);
@@ -514,6 +541,9 @@ bool RealCommandRunner::WaitForCommand(Result* result) {
     bool interrupted = subprocs_.DoWork();
     if (interrupted)
       return false;
+
+    result->status = ExitTimeout;
+    return true;
   }
 
   result->status = subproc->Finish();
@@ -681,6 +711,11 @@ bool Builder::Build(string* err) {
         return false;
       }
 
+      if (result.status == ExitTimeout) {
+        ReportProgress();
+        continue;
+      }
+
       --pending_commands;
       if (!FinishCommand(&result, err)) {
         status_->BuildFinished();
@@ -855,6 +890,14 @@ 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;
+  status_->BuildEdgeStillRunning(active_edges[0]);
+}
+
 bool Builder::ExtractDeps(CommandRunner::Result* result,
                           const string& deps_type,
                           vector<Node*>* deps_nodes,

src/build.h

@@ -36,6 +36,9 @@ struct Edge;
 struct Node;
 struct State;
 
+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 {
@@ -168,6 +171,8 @@ struct Builder {
   /// @return false if the build can not proceed further due to a fatal error.
   bool FinishCommand(CommandRunner::Result* result, string* err);
 
+  void ReportProgress(void);
+
   bool ConsiderRestartingCommand(CommandRunner::Result* result, string* err);
 
   /// Used for tests.
@@ -200,6 +205,7 @@ struct BuildStatus {
   void BuildEdgeStarted(Edge* edge);
   void BuildEdgeFinished(Edge* edge, bool success, const string& output,
                          int* start_time, int* end_time);
+  void BuildEdgeStillRunning(Edge* edge);
   void BuildEdgeShouldRestart();
   void BuildFinished();
 
@@ -210,7 +216,8 @@ struct BuildStatus {
   string FormatProgressStatus(const char* progress_status_format) const;
 
  private:
-  void PrintStatus(Edge* edge);
+  void PrintStatus(Edge* edge, const char* trailer = "");
+  void RestartStillRunningDelay();
 
   const BuildConfig& config_;
 
@@ -226,6 +233,10 @@ struct BuildStatus {
   /// 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_;
+
   /// The custom progress status format to use.
   const char* progress_status_format_;
 

src/exit_status.h

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

src/subprocess-posix.cc

@@ -193,14 +193,19 @@ bool SubprocessSet::DoWork() {
     ++nfds;
   }
 
+
   interrupted_ = false;
-  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 interrupted_;
+  }else if (ret == 0) {
+    // Timeout
+    return false;
   }
 
   nfds_t cur_nfd = 0;
@@ -241,13 +246,17 @@ bool SubprocessSet::DoWork() {
   }
 
   interrupted_ = false;
-  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 interrupted_;
+  }else if (ret == 0) {
+    // Timeout
+    return false;
   }
 
   for (vector<Subprocess*>::iterator i = running_.begin();

src/subprocess.h

@@ -95,4 +95,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_