| // Copyright 2016 Google Inc. All Rights Reserved. |
| // |
| // Licensed under the Apache License, Version 2.0 (the "License"); |
| // you may not use this file except in compliance with the License. |
| // You may obtain a copy of the License at |
| // |
| // http://www.apache.org/licenses/LICENSE-2.0 |
| // |
| // Unless required by applicable law or agreed to in writing, software |
| // distributed under the License is distributed on an "AS IS" BASIS, |
| // WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. |
| // See the License for the specific language governing permissions and |
| // limitations under the License. |
| |
| #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> |
| |
| #ifdef _WIN32 |
| #include <fcntl.h> |
| #include <io.h> |
| #endif |
| |
| #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) { |
| // Don't do anything fancy in verbose mode. |
| if (config_.verbosity != BuildConfig::NORMAL) |
| printer_.set_smart_terminal(false); |
| |
| progress_status_format_ = getenv("NINJA_STATUS"); |
| if (!progress_status_format_) |
| progress_status_format_ = "[%f/%t] "; |
| } |
| |
| 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, |
| int64_t start_time_millis) { |
| ++started_edges_; |
| ++running_edges_; |
| time_millis_ = start_time_millis; |
| |
| if (edge->use_console() || printer_.is_smart_terminal()) |
| PrintStatus(edge, start_time_millis); |
| |
| if (edge->use_console()) |
| printer_.SetConsoleLocked(true); |
| } |
| |
| 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); |
| |
| if (config_.verbosity == BuildConfig::QUIET) |
| return; |
| |
| if (!edge->use_console()) |
| PrintStatus(edge, end_time_millis); |
| |
| --running_edges_; |
| |
| // Print the command that is spewing before printing its output. |
| if (!success) { |
| string outputs; |
| for (vector<Node*>::const_iterator o = edge->outputs_.begin(); |
| o != edge->outputs_.end(); ++o) |
| outputs += (*o)->path() + " "; |
| |
| if (printer_.supports_color()) { |
| printer_.PrintOnNewLine("\x1B[31m" "FAILED: " "\x1B[0m" + outputs + "\n"); |
| } else { |
| printer_.PrintOnNewLine("FAILED: " + outputs + "\n"); |
| } |
| printer_.PrintOnNewLine(edge->EvaluateCommand() + "\n"); |
| } |
| |
| if (!output.empty()) { |
| // ninja sets stdout and stderr of subprocesses to a pipe, to be able to |
| // check if the output is empty. Some compilers, e.g. clang, check |
| // isatty(stderr) to decide if they should print colored output. |
| // To make it possible to use colored output with ninja, subprocesses should |
| // be run with a flag that forces them to always print color escape codes. |
| // To make sure these escape codes don't show up in a file if ninja's output |
| // is piped to a file, ninja strips ansi escape codes again if it's not |
| // writing to a |smart_terminal_|. |
| // (Launching subprocesses in pseudo ttys doesn't work because there are |
| // only a few hundred available on some systems, and ninja can launch |
| // thousands of parallel compile commands.) |
| string final_output; |
| if (!printer_.supports_color()) |
| final_output = StripAnsiEscapeCodes(output); |
| else |
| final_output = output; |
| |
| #ifdef _WIN32 |
| // Fix extra CR being added on Windows, writing out CR CR LF (#773) |
| _setmode(_fileno(stdout), _O_BINARY); // Begin Windows extra CR fix |
| #endif |
| |
| printer_.PrintOnNewLine(final_output); |
| |
| #ifdef _WIN32 |
| _setmode(_fileno(stdout), _O_TEXT); // End Windows extra CR fix |
| #endif |
| } |
| } |
| |
| 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 |
| // this is done before the build starts, but our caller is about to |
| // load a dyndep file during the build. Doing so may generate more |
| // explanation lines (via fprintf directly to stderr), but in an |
| // interactive console the cursor is currently at the end of a status |
| // line. Start a new line so that the first explanation does not |
| // append to the status line. After the explanations are done a |
| // new build status line will appear. |
| if (g_explaining) |
| printer_.PrintOnNewLine(""); |
| } |
| |
| void StatusPrinter::BuildStarted() { |
| started_edges_ = 0; |
| finished_edges_ = 0; |
| running_edges_ = 0; |
| } |
| |
| void StatusPrinter::BuildFinished() { |
| printer_.SetConsoleLocked(false); |
| printer_.PrintOnNewLine(""); |
| } |
| |
| string StatusPrinter::FormatProgressStatus(const char* progress_status_format, |
| int64_t time_millis) const { |
| string out; |
| char buf[32]; |
| for (const char* s = progress_status_format; *s != '\0'; ++s) { |
| if (*s == '%') { |
| ++s; |
| switch (*s) { |
| case '%': |
| out.push_back('%'); |
| break; |
| |
| // Started edges. |
| case 's': |
| snprintf(buf, sizeof(buf), "%d", started_edges_); |
| out += buf; |
| break; |
| |
| // Total edges. |
| case 't': |
| snprintf(buf, sizeof(buf), "%d", total_edges_); |
| out += buf; |
| break; |
| |
| // Running edges. |
| case 'r': { |
| snprintf(buf, sizeof(buf), "%d", running_edges_); |
| out += buf; |
| break; |
| } |
| |
| // Unstarted edges. |
| case 'u': |
| snprintf(buf, sizeof(buf), "%d", total_edges_ - started_edges_); |
| out += buf; |
| break; |
| |
| // Finished edges. |
| case 'f': |
| snprintf(buf, sizeof(buf), "%d", finished_edges_); |
| out += buf; |
| break; |
| |
| // Overall finished edges per second. |
| case 'o': |
| SnprintfRate(finished_edges_ / (time_millis_ / 1e3), buf, "%.1f"); |
| out += buf; |
| break; |
| |
| // Current rate, average over the last '-j' jobs. |
| case 'c': |
| current_rate_.UpdateRate(finished_edges_, time_millis_); |
| SnprintfRate(current_rate_.rate(), buf, "%.1f"); |
| out += buf; |
| break; |
| |
| // Percentage of edges completed |
| case 'p': { |
| 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; |
| } |
| |
| #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; |
| } |
| |
| default: |
| Fatal("unknown placeholder '%%%c' in $NINJA_STATUS", *s); |
| return ""; |
| } |
| } else { |
| out.push_back(*s); |
| } |
| } |
| |
| return out; |
| } |
| |
| void StatusPrinter::PrintStatus(const Edge* edge, int64_t time_millis) { |
| if (config_.verbosity == BuildConfig::QUIET |
| || config_.verbosity == BuildConfig::NO_STATUS_UPDATE) |
| return; |
| |
| RecalculateProgressPrediction(); |
| |
| bool force_full_command = config_.verbosity == BuildConfig::VERBOSE; |
| |
| string to_print = edge->GetBinding("description"); |
| if (to_print.empty() || force_full_command) |
| to_print = edge->GetBinding("command"); |
| |
| to_print = FormatProgressStatus(progress_status_format_, time_millis) |
| + to_print; |
| |
| printer_.Print(to_print, |
| force_full_command ? LinePrinter::FULL : LinePrinter::ELIDE); |
| } |
| |
| void StatusPrinter::Warning(const char* msg, ...) { |
| va_list ap; |
| va_start(ap, msg); |
| ::Warning(msg, ap); |
| va_end(ap); |
| } |
| |
| void StatusPrinter::Error(const char* msg, ...) { |
| va_list ap; |
| va_start(ap, msg); |
| ::Error(msg, ap); |
| va_end(ap); |
| } |
| |
| void StatusPrinter::Info(const char* msg, ...) { |
| va_list ap; |
| va_start(ap, msg); |
| ::Info(msg, ap); |
| va_end(ap); |
| } |
