diff options
Diffstat (limited to 'src/status.cc')
-rw-r--r-- | src/status.cc | 210 |
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"); |