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"

#include <assert.h>
#include <stdarg.h>
#include <stdlib.h>

#ifdef _WIN32
#include <fcntl.h>
#include <io.h>
#undef min  // min() is defined as a macro in minwindef.h
#endif

#include "async_loop.h"
#include "build_config.h"
#include "debug_flags.h"

using namespace std;

namespace {

void StringAppendRate(std::string& str, double rate) {
  if (rate == -1)
    str.push_back('?');
  else
    StringAppendFormat(str, "%1.f", rate);
}

}  // namespace

StatusPrinter::StatusPrinter(const BuildConfig& config)
    : config_(config), started_edges_(0),
      finished_edges_(0), total_edges_(0), running_edges_(0), time_millis_(0),
      current_rate_(config.parallelism), format_(config_.status_format())  {
  // LinePrinter constructor uses these environment variables to determine
  // properties of the current terminal.
  printer_.Reset(config.environment.Get("TERM"),
                 config.environment.Get("CLICOLOR_FORCE"));

  // Don't do anything fancy in verbose mode.
  if (config_.verbosity != BuildConfig::NORMAL)
    printer_.set_smart_terminal(false);

  if (printer_.is_smart_terminal() && !config_.dry_run) {
    max_pending_height_ = config_.status_max_commands();

    // Since elapsed times are displayed to the first decimal digit
    // only, there is no point in using a value smaller than 0.1 seconds
    // for the refresh timeout.
    const int64_t minimal_refresh_timeout_ms = 100;
    int64_t config_refresh = config_.status_refresh_millis();
    if (config_refresh && config_refresh > minimal_refresh_timeout_ms)
      refresh_timeout_ms_ = config_refresh;
    else
      refresh_timeout_ms_ = minimal_refresh_timeout_ms;
  }
}

StatusPrinter::~StatusPrinter() = default;

void StatusPrinter::PlanHasTotalEdges(int total) {
  total_edges_ = total;
}

void StatusPrinter::BuildEdgeStarted(const Edge* edge) {
  int64_t start_time_millis = GetCurrentBuildTimeMs();
  ++started_edges_;
  ++running_edges_;
  time_millis_ = start_time_millis;

  pending_edges_[edge] = start_time_millis;

  if (edge->use_console()) {
    // This command will print its output directly to stdout, so
    // clear the pending edges to let Ninja update the status and
    // lock the line printer.
    DisableTimer();
    ClearPendingEdges();
    PrintStatus(edge, start_time_millis);
    printer_.SetConsoleLocked(true);
  } else if (printer_.is_smart_terminal()) {
    PrintStatus(edge, start_time_millis);
    BuildRefresh(start_time_millis);
  }
}

void StatusPrinter::BuildEdgeFinished(Edge* edge, bool success,
                                      const string& output) {
  int64_t end_time_millis = GetCurrentBuildTimeMs();
  time_millis_ = end_time_millis;
  ++finished_edges_;

  auto it = pending_edges_.find(edge);
  assert(it != pending_edges_.end());
  pending_edges_.erase(it);

  --running_edges_;

  if (edge->use_console()) {
    printer_.SetConsoleLocked(false);
    EnableTimer();
  }

  if (config_.verbosity == BuildConfig::QUIET)
    return;

  if (!edge->use_console()) {
    PrintStatus(edge, end_time_millis);
    if (success && output.empty()) {
      BuildRefresh(end_time_millis);
    } else {
      // Ninja is going to print something so clear
      // any pending edges first.
      ClearPendingEdges();
    }
  }

  // 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) {
    ClearPendingEdges();
    printer_.PrintOnNewLine("");
  }
}

void StatusPrinter::DisableTimer() {
  if (timer_)
    timer_.Cancel();
}

void StatusPrinter::EnableTimer() {
  if (timer_)
    timer_.SetDurationMs(refresh_timeout_ms_);
}

int64_t StatusPrinter::GetCurrentBuildTimeMs() const {
  return AsyncLoop::NowMs() - start_build_time_ms_;
}

void StatusPrinter::BuildStarted() {
  started_edges_ = 0;
  finished_edges_ = 0;
  running_edges_ = 0;

  if (refresh_timeout_ms_ > 0) {
    if (!timer_) {
      start_build_time_ms_ = AsyncLoop::NowMs();
      timer_ = AsyncTimer::CreateWithDuration(
          refresh_timeout_ms_, AsyncLoop::Get(), [this] {
            int64_t cur_time_ms = GetCurrentBuildTimeMs();
            BuildRefresh(cur_time_ms);
            timer_.SetDurationMs(refresh_timeout_ms_);
          });
    }
    EnableTimer();
  }

  // Reset last_update_time_ms_ because this function can be called
  // multiple times, but with different starting epochs, which can
  // confuse the logic in this code. As an example: Ninja starts
  // a build then decides to launch the regenerator, which takes
  // about 5 seconds to generate a new build plan. Ninja then starts
  // another build. Without the reset, pending commands will not be
  // displayed for about 5 seconds after the start of the second
  // build!
  last_update_time_ms_ = -1;
}

void StatusPrinter::BuildFinished() {
  if (timer_) {
    timer_.Close();
  }
  start_build_time_ms_ = 0;

  printer_.SetConsoleLocked(false);
  ClearPendingEdges();
  printer_.PrintOnNewLine("");
}

string StatusPrinter::FormatProgressStatus(const char* progress_status_format,
                                           int64_t time_millis) const {
  string out;
  for (const char* s = progress_status_format; *s != '\0'; ++s) {
    if (*s == '%') {
      ++s;
      switch (*s) {
      case '%':
        out.push_back('%');
        break;

        // Started edges.
      case 's':
        StringAppendFormat(out, "%d", started_edges_);
        break;

        // Total edges.
      case 't':
        StringAppendFormat(out, "%d", total_edges_);
        break;

        // Running edges.
      case 'r':
        StringAppendFormat(out, "%d", running_edges_);
        break;

        // Unstarted edges.
      case 'u':
        StringAppendFormat(out, "%d", total_edges_ - started_edges_);
        break;

        // Finished edges.
      case 'f':
        StringAppendFormat(out, "%d", finished_edges_);
        break;

        // Overall finished edges per second.
      case 'o':
        StringAppendRate(out, finished_edges_ / (time_millis_ / 1e3));
        break;

        // Current rate, average over the last '-j' jobs.
      case 'c':
        current_rate_.UpdateRate(finished_edges_, time_millis_);
        StringAppendRate(out, current_rate_.rate());
        break;

        // Percentage
      case 'p': {
        int percent = (100 * finished_edges_) / total_edges_;
        StringAppendFormat(out, "%3i%%", percent);
        break;
      }

      case 'e':
        StringAppendFormat(out, "%.3f", time_millis_ / 1e3);
        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;

  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(format_.c_str(), time_millis) +
             to_print;

  last_status_ = std::move(to_print);

  printer_.Print(last_status_,
                 force_full_command ? LinePrinter::FULL : LinePrinter::ELIDE);
}

void StatusPrinter::BuildRefresh(int64_t cur_time_ms) {
  if (last_update_time_ms_ >= 0) {
    int64_t since_last_ms = cur_time_ms - last_update_time_ms_;
    if (since_last_ms < refresh_timeout_ms_) {
      // No need to update more than necessary when tasks complete
      // really really fast.
      return;
    }
  }
  last_update_time_ms_ = cur_time_ms;
  PrintPendingEdges(cur_time_ms);
}

void StatusPrinter::ClearPendingEdges() {
  if (last_pending_height_ == 0)
    return;

  // repeat "go down 1 line; erase whole line" |last_height_| times.
  for (size_t n = 0; n < last_pending_height_; ++n) {
    printf("\x1B[1B\x1B[2K");
  }
  // move up |last_height_| lines.
  printf("\x1B[%dA", static_cast<int>(last_pending_height_));
  fflush(stdout);

  last_pending_height_ = 0;
}

void StatusPrinter::PrintPendingEdges(int64_t cur_time_ms) {
  if (!max_pending_height_)
    return;

  // Find the N-th older running edges, where N is max_height_.
  // Reuse the sorted_pending_edges_ vector between calls.
  auto& sorted_edges = sorted_pending_edges_;
  sorted_edges.assign(pending_edges_.begin(), pending_edges_.end());

  auto less = [](const EdgeInfo& a, const EdgeInfo& b) -> bool {
    return a.second < b.second;
  };
  size_t count = std::min(sorted_edges.size(), max_pending_height_);

  std::partial_sort(sorted_edges.begin(), sorted_edges.begin() + count,
                    sorted_edges.end(), less);

  std::string pending_line;
  for (size_t n = 0; n < count; ++n) {
    EdgeInfo& pair = sorted_edges[n];

    // Format the elapsed time in a human friendly format.
    std::string elapsed;
    int64_t elapsed_ms = cur_time_ms - pair.second;
    if (elapsed_ms < 0) {
      elapsed = "??????";
    } else {
      if (elapsed_ms < 60000) {
        StringAppendFormat(elapsed, "%d.%ds",
                           static_cast<int>((elapsed_ms / 1000)),
                           static_cast<int>((elapsed_ms % 1000) / 100));
      } else {
        StringAppendFormat(elapsed, "%dm%ds",
                           static_cast<int>((elapsed_ms / 60000)),
                           static_cast<int>((elapsed_ms % 60000) / 1000));
      }
    }

    // Get edge description or command.
    std::string description = pair.first->GetBinding("description");
    if (description.empty())
      description = pair.first->GetBinding("command");

    // Format '<elapsed> | <description>' where <elapsed> is
    // right-justified.
    size_t justification_width = 6;
    size_t justified_elapsed_width =
        std::min(justification_width, elapsed.size());
    size_t needed_capacity = justified_elapsed_width + 3 + description.size();
    if (needed_capacity > pending_line.capacity())
      pending_line.reserve(needed_capacity);
    if (elapsed.size() < justification_width) {
      pending_line.assign(justification_width - elapsed.size(), ' ');
    } else {
      pending_line.clear();
    }
    pending_line.append(elapsed);
    pending_line.append(" | ", 3);
    pending_line.append(description);

    printf("\n");
    printer_.Print(pending_line, LinePrinter::ELIDE);
  }

  // Clear previous lines that are not needed anymore.
  size_t next_height = count;
  for (; count < last_pending_height_; ++count) {
    // Go to next line + clear entire line.
    printf("\n\x1B[2K");
  }

  if (count > 0) {
    // Move up to the top status line. Then print the status
    // again to reposition the cursor to the right position.
    // Note that using ASCII sequences to save/restore the
    // cursor position does not work reliably in all terminals
    // (and terminal emulators like mosh or asciinema).
    printf("\x1B[%dA", static_cast<int>(count));
    printer_.Print(last_status_, LinePrinter::ELIDE);
  }

  last_pending_height_ = next_height;
}

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