1 files changed, 198 insertions, 12 deletions

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