Merge pull request #1963 from LebedevRI/reliable-eta

Reliable ETA and progress percentage.

8 files changed, 298 insertions, 38 deletions

diff --git a/doc/manual.asciidoc b/doc/manual.asciidoc
index 22601e1..d01b75a 100644
--- a/doc/manual.asciidoc
+++ b/doc/manual.asciidoc
@@ -204,7 +204,11 @@ Several placeholders are available:
 `%o`:: Overall rate of finished edges per second
 `%c`:: Current rate of finished edges per second (average over builds
 specified by `-j` or its default)
-`%e`:: Elapsed time in seconds.  _(Available since Ninja 1.2.)_
+`%e`:: Elapsed time in seconds. _(Available since Ninja 1.2.)_
+`%E`:: Remaining time (ETA) in seconds. _(Available since Ninja 1.12.)_
+`%w`:: Elapsed time in [h:]mm:ss format. _(Available since Ninja 1.12.)_
+`%W`:: Remaining time (ETA) in [h:]mm:ss format. _(Available since Ninja 1.12.)_
+`%P`:: The percentage (in ppp% format) of time elapsed out of predicted total runtime. _(Available since Ninja 1.12.)_
 `%%`:: A plain `%` character.
 
 The default progress status is `"[%f/%t] "` (note the trailing space
diff --git a/src/build.cc b/src/build.cc
index 9c5cb66..7e2ccfa 100644
--- a/src/build.cc
+++ b/src/build.cc
@@ -150,8 +150,11 @@ bool Plan::AddSubTarget(const Node* node, const Node* dependent, string* err,
 
 void Plan::EdgeWanted(const Edge* edge) {
   ++wanted_edges_;
-  if (!edge->is_phony())
+  if (!edge->is_phony()) {
     ++command_edges_;
+    if (builder_)
+      builder_->status_->EdgeAddedToPlan(edge);
+  }
 }
 
 Edge* Plan::FindWork() {
@@ -300,8 +303,11 @@ bool Plan::CleanNode(DependencyScan* scan, Node* node, string* err) {
 
         want_e->second = kWantNothing;
         --wanted_edges_;
-        if (!(*oe)->is_phony())
+        if (!(*oe)->is_phony()) {
           --command_edges_;
+          if (builder_)
+            builder_->status_->EdgeRemovedFromPlan(*oe);
+        }
       }
     }
   }
@@ -743,7 +749,6 @@ bool Builder::Build(string* err) {
   assert(!AlreadyUpToDate());
   plan_.PrepareQueue();
 
-  status_->PlanHasTotalEdges(plan_.command_edge_count());
   int pending_commands = 0;
   int failures_allowed = config_.failures_allowed;
 
@@ -929,8 +934,8 @@ bool Builder::FinishCommand(CommandRunner::Result* result, string* err) {
   end_time_millis = GetTimeMillis() - start_time_millis_;
   running_edges_.erase(it);
 
-  status_->BuildEdgeFinished(edge, end_time_millis, result->success(),
-                             result->output);
+  status_->BuildEdgeFinished(edge, start_time_millis, end_time_millis,
+                             result->success(), result->output);
 
   // The rest of this function only applies to successful commands.
   if (!result->success()) {
@@ -970,10 +975,6 @@ bool Builder::FinishCommand(CommandRunner::Result* result, string* err) {
     }
     if (node_cleaned) {
       record_mtime = edge->command_start_time_;
-
-      // The total number of edges in the plan may have changed as a result
-      // of a restat.
-      status_->PlanHasTotalEdges(plan_.command_edge_count());
     }
   }
 
@@ -1087,8 +1088,5 @@ bool Builder::LoadDyndeps(Node* node, string* err) {
   if (!plan_.DyndepsLoaded(&scan_, node, ddf, err))
     return false;
 
-  // New command edges may have been added to the plan.
-  status_->PlanHasTotalEdges(plan_.command_edge_count());
-
   return true;
 }
diff --git a/src/build_test.cc b/src/build_test.cc
index 429e71c..61b0b6a 100644
--- a/src/build_test.cc
+++ b/src/build_test.cc
@@ -2257,11 +2257,28 @@ TEST_F(BuildTest, DepsGccWithEmptyDepfileErrorsOut) {
   ASSERT_EQ(1u, command_runner_.commands_ran_.size());
 }
 
-TEST_F(BuildTest, StatusFormatElapsed) {
+TEST_F(BuildTest, StatusFormatElapsed_e) {
   status_.BuildStarted();
   // Before any task is done, the elapsed time must be zero.
-  EXPECT_EQ("[%/e0.000]",
-            status_.FormatProgressStatus("[%%/e%e]", 0));
+  EXPECT_EQ("[%/e0.000]", status_.FormatProgressStatus("[%%/e%e]", 0));
+}
+
+TEST_F(BuildTest, StatusFormatElapsed_w) {
+  status_.BuildStarted();
+  // Before any task is done, the elapsed time must be zero.
+  EXPECT_EQ("[%/e00:00]", status_.FormatProgressStatus("[%%/e%w]", 0));
+}
+
+TEST_F(BuildTest, StatusFormatETA) {
+  status_.BuildStarted();
+  // Before any task is done, the ETA time must be unknown.
+  EXPECT_EQ("[%/E?]", status_.FormatProgressStatus("[%%/E%E]", 0));
+}
+
+TEST_F(BuildTest, StatusFormatTimeProgress) {
+  status_.BuildStarted();
+  // Before any task is done, the percentage of elapsed time must be zero.
+  EXPECT_EQ("[%/p  0%]", status_.FormatProgressStatus("[%%/p%p]", 0));
 }
 
 TEST_F(BuildTest, StatusFormatReplacePlaceholder) {
diff --git a/src/graph.h b/src/graph.h
index d49c309..825ef36 100644
--- a/src/graph.h
+++ b/src/graph.h
@@ -276,6 +276,10 @@ struct Edge {
   bool is_phony() const;
   bool use_console() const;
   bool maybe_phonycycle_diagnostic() const;
+
+  // Historical info: how long did this edge take last time,
+  // as per .ninja_log, if known? Defaults to -1 if unknown.
+  int64_t prev_elapsed_time_millis = -1;
 };
 
 struct EdgeCmp {
diff --git a/src/ninja.cc b/src/ninja.cc
index 839e9e6..ce1beda 100644
--- a/src/ninja.cc
+++ b/src/ninja.cc
@@ -153,6 +153,10 @@ struct NinjaMain : public BuildLogUser {
   /// @return true if the manifest was rebuilt.
   bool RebuildManifest(const char* input_file, string* err, Status* status);
 
+  /// For each edge, lookup in build log how long it took last time,
+  /// and record that in the edge itself. It will be used for ETA predicton.
+  void ParsePreviousElapsedTimes();
+
   /// Build the targets listed on the command line.
   /// @return an exit code.
   int RunBuild(int argc, char** argv, Status* status);
@@ -286,6 +290,19 @@ bool NinjaMain::RebuildManifest(const char* input_file, string* err,
   return true;
 }
 
+void NinjaMain::ParsePreviousElapsedTimes() {
+  for (Edge* edge : state_.edges_) {
+    for (Node* out : edge->outputs_) {
+      BuildLog::LogEntry* log_entry = build_log_.LookupByOutput(out->path());
+      if (!log_entry)
+        continue;  // Maybe we'll have log entry for next output of this edge?
+      edge->prev_elapsed_time_millis =
+          log_entry->end_time - log_entry->start_time;
+      break;  // Onto next edge.
+    }
+  }
+}
+
 Node* NinjaMain::CollectTarget(const char* cpath, string* err) {
   string path = cpath;
   if (path.empty()) {
@@ -1586,6 +1603,8 @@ NORETURN void real_main(int argc, char** argv) {
       exit(1);
     }
 
+    ninja.ParsePreviousElapsedTimes();
+
     int result = ninja.RunBuild(argc, argv, status);
     if (g_metrics)
       ninja.DumpMetrics();
diff --git a/src/status.cc b/src/status.cc
index 88b7781..06f3c20 100644
--- a/src/status.cc
+++ b/src/status.cc
@@ -14,6 +14,15 @@
 
 #include "status.h"
 
+#ifdef _WIN32
+#include "win32port.h"
+#else
+#ifndef __STDC_FORMAT_MACROS
+#define __STDC_FORMAT_MACROS
+#endif
+#include <cinttypes>
+#endif
+
 #include <stdarg.h>
 #include <stdlib.h>
 
@@ -27,11 +36,9 @@
 using namespace std;
 
 StatusPrinter::StatusPrinter(const BuildConfig& config)
-    : config_(config),
-      started_edges_(0), finished_edges_(0), total_edges_(0), running_edges_(0),
-      time_millis_(0), progress_status_format_(NULL),
+    : config_(config), started_edges_(0), finished_edges_(0), total_edges_(0),
+      running_edges_(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);
@@ -41,8 +48,32 @@ StatusPrinter::StatusPrinter(const BuildConfig& config)
     progress_status_format_ = "[%f/%t] ";
 }
 
-void StatusPrinter::PlanHasTotalEdges(int total) {
-  total_edges_ = total;
+void StatusPrinter::EdgeAddedToPlan(const Edge* edge) {
+  ++total_edges_;
+
+  // Do we know how long did this edge take last time?
+  if (edge->prev_elapsed_time_millis != -1) {
+    ++eta_predictable_edges_total_;
+    ++eta_predictable_edges_remaining_;
+    eta_predictable_cpu_time_total_millis_ += edge->prev_elapsed_time_millis;
+    eta_predictable_cpu_time_remaining_millis_ +=
+        edge->prev_elapsed_time_millis;
+  } else
+    ++eta_unpredictable_edges_remaining_;
+}
+
+void StatusPrinter::EdgeRemovedFromPlan(const Edge* edge) {
+  --total_edges_;
+
+  // Do we know how long did this edge take last time?
+  if (edge->prev_elapsed_time_millis != -1) {
+    --eta_predictable_edges_total_;
+    --eta_predictable_edges_remaining_;
+    eta_predictable_cpu_time_total_millis_ -= edge->prev_elapsed_time_millis;
+    eta_predictable_cpu_time_remaining_millis_ -=
+        edge->prev_elapsed_time_millis;
+  } else
+    --eta_unpredictable_edges_remaining_;
 }
 
 void StatusPrinter::BuildEdgeStarted(const Edge* edge,
@@ -58,11 +89,102 @@ void StatusPrinter::BuildEdgeStarted(const Edge* edge,
     printer_.SetConsoleLocked(true);
 }
 
-void StatusPrinter::BuildEdgeFinished(Edge* edge, int64_t end_time_millis,
-                                      bool success, const string& output) {
+void StatusPrinter::RecalculateProgressPrediction() {
+  time_predicted_percentage_ = 0.0;
+
+  // Sometimes, the previous and actual times may be wildly different.
+  // For example, the previous build may have been fully recovered from ccache,
+  // so it was blazing fast, while the new build no longer gets hits from ccache
+  // for whatever reason, so it actually compiles code, which takes much longer.
+  // We should detect such cases, and avoid using "wrong" previous times.
+
+  // Note that we will only use the previous times if there are edges with
+  // previous time knowledge remaining.
+  bool use_previous_times = eta_predictable_edges_remaining_ &&
+                            eta_predictable_cpu_time_remaining_millis_;
+
+  // Iff we have sufficient statistical information for the current run,
+  // that is, if we have took at least 15 sec AND finished at least 5% of edges,
+  // we can check whether our performance so far matches the previous one.
+  if (use_previous_times && total_edges_ && finished_edges_ &&
+      (time_millis_ >= 15 * 1e3) &&
+      (((double)finished_edges_ / total_edges_) >= 0.05)) {
+    // Over the edges we've just run, how long did they take on average?
+    double actual_average_cpu_time_millis =
+        (double)cpu_time_millis_ / finished_edges_;
+    // What is the previous average, for the edges with such knowledge?
+    double previous_average_cpu_time_millis =
+        (double)eta_predictable_cpu_time_total_millis_ /
+        eta_predictable_edges_total_;
+
+    double ratio = std::max(previous_average_cpu_time_millis,
+                            actual_average_cpu_time_millis) /
+                   std::min(previous_average_cpu_time_millis,
+                            actual_average_cpu_time_millis);
+
+    // Let's say that the average times should differ by less than 10x
+    use_previous_times = ratio < 10;
+  }
+
+  int edges_with_known_runtime = finished_edges_;
+  if (use_previous_times)
+    edges_with_known_runtime += eta_predictable_edges_remaining_;
+  if (edges_with_known_runtime == 0)
+    return;
+
+  int edges_with_unknown_runtime = use_previous_times
+                                       ? eta_unpredictable_edges_remaining_
+                                       : (total_edges_ - finished_edges_);
+
+  // Given the time elapsed on the edges we've just run,
+  // and the runtime of the edges for which we know previous runtime,
+  // what's the edge's average runtime?
+  int64_t edges_known_runtime_total_millis = cpu_time_millis_;
+  if (use_previous_times)
+    edges_known_runtime_total_millis +=
+        eta_predictable_cpu_time_remaining_millis_;
+
+  double average_cpu_time_millis =
+      (double)edges_known_runtime_total_millis / edges_with_known_runtime;
+
+  // For the edges for which we do not have the previous runtime,
+  // let's assume that their average runtime is the same as for the other edges,
+  // and we therefore can predict their remaining runtime.
+  double unpredictable_cpu_time_remaining_millis =
+      average_cpu_time_millis * edges_with_unknown_runtime;
+
+  // And therefore we can predict the remaining and total runtimes.
+  double total_cpu_time_remaining_millis =
+      unpredictable_cpu_time_remaining_millis;
+  if (use_previous_times)
+    total_cpu_time_remaining_millis +=
+        eta_predictable_cpu_time_remaining_millis_;
+  double total_cpu_time_millis =
+      cpu_time_millis_ + total_cpu_time_remaining_millis;
+  if (total_cpu_time_millis == 0.0)
+    return;
+
+  // After that we can tell how much work we've completed, in time units.
+  time_predicted_percentage_ = cpu_time_millis_ / total_cpu_time_millis;
+}
+
+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;
+
+  // Do we know how long did this edge take last time?
+  if (edge->prev_elapsed_time_millis != -1) {
+    --eta_predictable_edges_remaining_;
+    eta_predictable_cpu_time_remaining_millis_ -=
+        edge->prev_elapsed_time_millis;
+  } else
+    --eta_unpredictable_edges_remaining_;
+
   if (edge->use_console())
     printer_.SetConsoleLocked(false);
 
@@ -201,16 +323,78 @@ string StatusPrinter::FormatProgressStatus(const char* progress_status_format,
         out += buf;
         break;
 
-        // Percentage
+        // Percentage of edges completed
       case 'p': {
-        int percent = (100 * finished_edges_) / total_edges_;
+        int percent = 0;
+        if (finished_edges_ != 0 && total_edges_ != 0)
+          percent = (100 * finished_edges_) / total_edges_;
         snprintf(buf, sizeof(buf), "%3i%%", percent);
         out += buf;
         break;
       }
 
-      case 'e': {
-        snprintf(buf, sizeof(buf), "%.3f", time_millis_ / 1e3);
+#define FORMAT_TIME_HMMSS(t)                                                \
+  "%" PRId64 ":%02" PRId64 ":%02" PRId64 "", (t) / 3600, ((t) % 3600) / 60, \
+      (t) % 60
+#define FORMAT_TIME_MMSS(t) "%02" PRId64 ":%02" PRId64 "", (t) / 60, (t) % 60
+
+        // Wall time
+      case 'e':  // elapsed, seconds
+      case 'w':  // elapsed, human-readable
+      case 'E':  // ETA, seconds
+      case 'W':  // ETA, human-readable
+      {
+        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,
+          // 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_;
+          // Naturally, that gives us the time remaining.
+          eta_sec = (total_wall_time - time_millis_) / 1e3;
+        }
+
+        const bool print_with_hours =
+            elapsed_sec >= 60 * 60 || eta_sec >= 60 * 60;
+
+        double sec = -1;
+        switch (*s) {
+        case 'e':  // elapsed, seconds
+        case 'w':  // elapsed, human-readable
+          sec = elapsed_sec;
+          break;
+        case 'E':  // ETA, seconds
+        case 'W':  // ETA, human-readable
+          sec = eta_sec;
+          break;
+        }
+
+        if (sec < 0)
+          snprintf(buf, sizeof(buf), "?");
+        else {
+          switch (*s) {
+          case 'e':  // elapsed, seconds
+          case 'E':  // ETA, seconds
+            snprintf(buf, sizeof(buf), "%.3f", sec);
+            break;
+          case 'w':  // elapsed, human-readable
+          case 'W':  // ETA, human-readable
+            if (print_with_hours)
+              snprintf(buf, sizeof(buf), FORMAT_TIME_HMMSS((int64_t)sec));
+            else
+              snprintf(buf, sizeof(buf), FORMAT_TIME_MMSS((int64_t)sec));
+            break;
+          }
+        }
+        out += buf;
+        break;
+      }
+
+      // Percentage of time spent out of the predicted time total
+      case 'P': {
+        snprintf(buf, sizeof(buf), "%3i%%",
+                 (int)(100. * time_predicted_percentage_));
         out += buf;
         break;
       }
@@ -232,6 +416,8 @@ void StatusPrinter::PrintStatus(const Edge* edge, int64_t time_millis) {
       || config_.verbosity == BuildConfig::NO_STATUS_UPDATE)
     return;
 
+  RecalculateProgressPrediction();
+
   bool force_full_command = config_.verbosity == BuildConfig::VERBOSE;
 
   string to_print = edge->GetBinding("description");
diff --git a/src/status.h b/src/status.h
index b2e50ea..a1a8fdd 100644
--- a/src/status.h
+++ b/src/status.h
@@ -24,10 +24,13 @@
 /// Abstract interface to object that tracks the status of a build:
 /// completion fraction, printing updates.
 struct Status {
-  virtual void PlanHasTotalEdges(int total) = 0;
-  virtual void BuildEdgeStarted(const Edge* edge, int64_t start_time_millis) = 0;
-  virtual void BuildEdgeFinished(Edge* edge, int64_t end_time_millis,
-                                 bool success, const std::string& output) = 0;
+  virtual void EdgeAddedToPlan(const Edge* edge) = 0;
+  virtual void EdgeRemovedFromPlan(const Edge* edge) = 0;
+  virtual void BuildEdgeStarted(const Edge* edge,
+                                int64_t start_time_millis) = 0;
+  virtual void BuildEdgeFinished(Edge* edge, int64_t start_time_millis,
+                                 int64_t end_time_millis, bool success,
+                                 const std::string& output) = 0;
   virtual void BuildLoadDyndeps() = 0;
   virtual void BuildStarted() = 0;
   virtual void BuildFinished() = 0;
@@ -43,10 +46,15 @@ struct Status {
 /// human-readable strings to stdout
 struct StatusPrinter : Status {
   explicit StatusPrinter(const BuildConfig& config);
-  virtual void PlanHasTotalEdges(int total);
+
+  /// Callbacks for the Plan to notify us about adding/removing Edge's.
+  virtual void EdgeAddedToPlan(const Edge* edge);
+  virtual void EdgeRemovedFromPlan(const Edge* edge);
+
   virtual void BuildEdgeStarted(const Edge* edge, int64_t start_time_millis);
-  virtual void BuildEdgeFinished(Edge* edge, int64_t end_time_millis,
-                                 bool success, const std::string& output);
+  virtual void BuildEdgeFinished(Edge* edge, int64_t start_time_millis,
+                                 int64_t end_time_millis, bool success,
+                                 const std::string& output);
   virtual void BuildLoadDyndeps();
   virtual void BuildStarted();
   virtual void BuildFinished();
@@ -71,7 +79,30 @@ struct StatusPrinter : Status {
   const BuildConfig& config_;
 
   int started_edges_, finished_edges_, total_edges_, running_edges_;
-  int64_t time_millis_;
+
+  /// How much wall clock elapsed so far?
+  int64_t time_millis_ = 0;
+
+  /// How much cpu clock elapsed so far?
+  int64_t cpu_time_millis_ = 0;
+
+  /// What percentage of predicted total time have elapsed already?
+  double time_predicted_percentage_ = 0.0;
+
+  /// Out of all the edges, for how many do we know previous time?
+  int eta_predictable_edges_total_ = 0;
+  /// And how much time did they all take?
+  int64_t eta_predictable_cpu_time_total_millis_ = 0;
+
+  /// Out of all the non-finished edges, for how many do we know previous time?
+  int eta_predictable_edges_remaining_ = 0;
+  /// And how much time will they all take?
+  int64_t eta_predictable_cpu_time_remaining_millis_ = 0;
+
+  /// For how many edges we don't know the previous run time?
+  int eta_unpredictable_edges_remaining_ = 0;
+
+  void RecalculateProgressPrediction();
 
   /// Prints progress output.
   LinePrinter printer_;
diff --git a/src/status_test.cc b/src/status_test.cc
index 6e42490..411d3ed 100644
--- a/src/status_test.cc
+++ b/src/status_test.cc
@@ -22,8 +22,9 @@ TEST(StatusTest, StatusFormatElapsed) {
 
   status.BuildStarted();
   // Before any task is done, the elapsed time must be zero.
-  EXPECT_EQ("[%/e0.000]",
-            status.FormatProgressStatus("[%%/e%e]", 0));
+  EXPECT_EQ("[%/e0.000]", status.FormatProgressStatus("[%%/e%e]", 0));
+  // Before any task is done, the elapsed time must be zero.
+  EXPECT_EQ("[%/e00:00]", status.FormatProgressStatus("[%%/e%w]", 0));
 }
 
 TEST(StatusTest, StatusFormatReplacePlaceholder) {