ninja/src/status.cc

// 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);
}