Move edge time from Status to Builder
The times that end up in the build log currently originate in the
status printer, and are propagated back out to the Builder. Move
the edge times into the Builder instead, and move the overall start
time into NinjaMain so it doesn't get reset during manifest
rebuilds.
diff --git a/src/build.cc b/src/build.cc
index 2007d82..f04e2f2 100644
--- a/src/build.cc
+++ b/src/build.cc
@@ -36,6 +36,7 @@
#include "deps_log.h"
#include "disk_interface.h"
#include "graph.h"
+#include "metrics.h"
#include "state.h"
#include "subprocess.h"
#include "util.h"
@@ -79,8 +80,9 @@
} // namespace
BuildStatus::BuildStatus(const BuildConfig& config)
- : config_(config), start_time_millis_(GetTimeMillis()), started_edges_(0),
- finished_edges_(0), total_edges_(0), progress_status_format_(NULL),
+ : config_(config),
+ started_edges_(0), finished_edges_(0), total_edges_(0),
+ time_millis_(0), progress_status_format_(NULL),
current_rate_(config.parallelism) {
// Don't do anything fancy in verbose mode.
if (config_.verbosity != BuildConfig::NORMAL)
@@ -95,33 +97,24 @@
total_edges_ = total;
}
-void BuildStatus::BuildEdgeStarted(const Edge* edge) {
- assert(running_edges_.find(edge) == running_edges_.end());
- int start_time = (int)(GetTimeMillis() - start_time_millis_);
- running_edges_.insert(make_pair(edge, start_time));
+void BuildStatus::BuildEdgeStarted(const Edge* edge,
+ int64_t start_time_millis) {
++started_edges_;
+ time_millis_ = start_time_millis;
if (edge->use_console() || printer_.is_smart_terminal())
- PrintStatus(edge, kEdgeStarted);
+ PrintStatus(edge, start_time_millis, kEdgeStarted);
if (edge->use_console())
printer_.SetConsoleLocked(true);
}
-void BuildStatus::BuildEdgeFinished(Edge* edge,
+void BuildStatus::BuildEdgeFinished(Edge* edge, int64_t end_time_millis,
bool success,
- const string& output,
- int* start_time,
- int* end_time) {
- int64_t now = GetTimeMillis();
-
+ const string& output) {
+ time_millis_ = end_time_millis;
++finished_edges_;
- RunningEdgeMap::iterator i = running_edges_.find(edge);
- *start_time = i->second;
- *end_time = (int)(now - start_time_millis_);
- running_edges_.erase(i);
-
if (edge->use_console())
printer_.SetConsoleLocked(false);
@@ -129,7 +122,7 @@
return;
if (!edge->use_console())
- PrintStatus(edge, kEdgeFinished);
+ PrintStatus(edge, end_time_millis, kEdgeFinished);
// Print the command that is spewing before printing its output.
if (!success) {
@@ -192,8 +185,6 @@
}
void BuildStatus::BuildStarted() {
- overall_rate_.Restart();
- current_rate_.Restart();
}
void BuildStatus::BuildFinished() {
@@ -202,10 +193,9 @@
}
string BuildStatus::FormatProgressStatus(
- const char* progress_status_format, EdgeStatus status) const {
+ const char* progress_status_format, int64_t time, EdgeStatus status) const {
string out;
char buf[32];
- int percent;
for (const char* s = progress_status_format; *s != '\0'; ++s) {
if (*s == '%') {
++s;
@@ -251,28 +241,27 @@
// Overall finished edges per second.
case 'o':
- overall_rate_.UpdateRate(finished_edges_);
- SnprintfRate(overall_rate_.rate(), buf, "%.1f");
+ 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_);
+ current_rate_.UpdateRate(finished_edges_, time_millis_);
SnprintfRate(current_rate_.rate(), buf, "%.1f");
out += buf;
break;
// Percentage
- case 'p':
- percent = (100 * finished_edges_) / total_edges_;
+ case 'p': {
+ int percent = (100 * finished_edges_) / total_edges_;
snprintf(buf, sizeof(buf), "%3i%%", percent);
out += buf;
break;
+ }
case 'e': {
- double elapsed = overall_rate_.Elapsed();
- snprintf(buf, sizeof(buf), "%.3f", elapsed);
+ snprintf(buf, sizeof(buf), "%.3f", time_millis_ / 1e3);
out += buf;
break;
}
@@ -289,7 +278,7 @@
return out;
}
-void BuildStatus::PrintStatus(const Edge* edge, EdgeStatus status) {
+void BuildStatus::PrintStatus(const Edge* edge, int64_t time, EdgeStatus status) {
if (config_.verbosity == BuildConfig::QUIET)
return;
@@ -299,7 +288,7 @@
if (to_print.empty() || force_full_command)
to_print = edge->GetBinding("command");
- to_print = FormatProgressStatus(progress_status_format_, status) + to_print;
+ to_print = FormatProgressStatus(progress_status_format_, time, status) + to_print;
printer_.Print(to_print,
force_full_command ? LinePrinter::FULL : LinePrinter::ELIDE);
@@ -729,9 +718,9 @@
Builder::Builder(State* state, const BuildConfig& config,
BuildLog* build_log, DepsLog* deps_log,
- DiskInterface* disk_interface)
- : state_(state), config_(config),
- plan_(this), disk_interface_(disk_interface),
+ DiskInterface* disk_interface, int64_t start_time_millis)
+ : state_(state), config_(config), plan_(this),
+ start_time_millis_(start_time_millis), disk_interface_(disk_interface),
scan_(state, build_log, deps_log, disk_interface,
&config_.depfile_parser_options) {
status_ = new BuildStatus(config);
@@ -904,7 +893,10 @@
if (edge->is_phony())
return true;
- status_->BuildEdgeStarted(edge);
+ int64_t start_time_millis = GetTimeMillis() - start_time_millis_;
+ running_edges_.insert(make_pair(edge, start_time_millis));
+
+ status_->BuildEdgeStarted(edge, start_time_millis);
// Create directories necessary for outputs.
// XXX: this will block; do we care?
@@ -957,9 +949,14 @@
}
}
- int start_time, end_time;
- status_->BuildEdgeFinished(edge, result->success(), result->output,
- &start_time, &end_time);
+ int64_t start_time_millis, end_time_millis;
+ RunningEdgeMap::iterator it = running_edges_.find(edge);
+ start_time_millis = it->second;
+ end_time_millis = GetTimeMillis() - start_time_millis_;
+ running_edges_.erase(it);
+
+ status_->BuildEdgeFinished(edge, end_time_millis, result->success(),
+ result->output);
// The rest of this function only applies to successful commands.
if (!result->success()) {
@@ -1028,8 +1025,8 @@
disk_interface_->RemoveFile(rspfile);
if (scan_.build_log()) {
- if (!scan_.build_log()->RecordCommand(edge, start_time, end_time,
- output_mtime)) {
+ if (!scan_.build_log()->RecordCommand(edge, start_time_millis,
+ end_time_millis, output_mtime)) {
*err = string("Error writing to build log: ") + strerror(errno);
return false;
}
diff --git a/src/build.h b/src/build.h
index 0a68478..6935086 100644
--- a/src/build.h
+++ b/src/build.h
@@ -26,7 +26,6 @@
#include "graph.h" // XXX needed for DependencyScan; should rearrange.
#include "exit_status.h"
#include "line_printer.h"
-#include "metrics.h"
#include "util.h" // int64_t
struct BuildLog;
@@ -179,7 +178,7 @@
struct Builder {
Builder(State* state, const BuildConfig& config,
BuildLog* build_log, DepsLog* deps_log,
- DiskInterface* disk_interface);
+ DiskInterface* disk_interface, int64_t start_time_millis);
~Builder();
/// Clean up after interrupted commands by deleting output files.
@@ -227,6 +226,13 @@
const std::string& deps_prefix,
std::vector<Node*>* deps_nodes, std::string* err);
+ /// Map of running edge to time the edge started running.
+ typedef std::map<const Edge*, int> RunningEdgeMap;
+ RunningEdgeMap running_edges_;
+
+ /// Time the build started.
+ int64_t start_time_millis_;
+
DiskInterface* disk_interface_;
DependencyScan scan_;
@@ -239,9 +245,9 @@
struct BuildStatus {
explicit BuildStatus(const BuildConfig& config);
void PlanHasTotalEdges(int total);
- void BuildEdgeStarted(const Edge* edge);
- void BuildEdgeFinished(Edge* edge, bool success, const std::string& output,
- int* start_time, int* end_time);
+ void BuildEdgeStarted(const Edge* edge, int64_t start_time_millis);
+ void BuildEdgeFinished(Edge* edge, int64_t end_time_millis, bool success,
+ const std::string& output);
void BuildLoadDyndeps();
void BuildStarted();
void BuildFinished();
@@ -257,21 +263,15 @@
/// @param progress_status_format The format of the progress status.
/// @param status The status of the edge.
std::string FormatProgressStatus(const char* progress_status_format,
- EdgeStatus status) const;
+ int64_t time, EdgeStatus status) const;
private:
- void PrintStatus(const Edge* edge, EdgeStatus status);
+ void PrintStatus(const Edge* edge, int64_t time, EdgeStatus status);
const BuildConfig& config_;
- /// Time the build started.
- int64_t start_time_millis_;
-
int started_edges_, finished_edges_, total_edges_;
-
- /// Map of running edge to time the edge started running.
- typedef std::map<const Edge*, int> RunningEdgeMap;
- RunningEdgeMap running_edges_;
+ int64_t time_millis_;
/// Prints progress output.
LinePrinter printer_;
@@ -287,50 +287,30 @@
snprintf(buf, S, format, rate);
}
- struct RateInfo {
- RateInfo() : rate_(-1) {}
-
- void Restart() { stopwatch_.Restart(); }
- double Elapsed() const { return stopwatch_.Elapsed(); }
- double rate() { return rate_; }
-
- void UpdateRate(int edges) {
- if (edges && stopwatch_.Elapsed())
- rate_ = edges / stopwatch_.Elapsed();
- }
-
- private:
- double rate_;
- Stopwatch stopwatch_;
- };
-
struct SlidingRateInfo {
SlidingRateInfo(int n) : rate_(-1), N(n), last_update_(-1) {}
- void Restart() { stopwatch_.Restart(); }
double rate() { return rate_; }
- void UpdateRate(int update_hint) {
+ void UpdateRate(int update_hint, int64_t time_millis_) {
if (update_hint == last_update_)
return;
last_update_ = update_hint;
if (times_.size() == N)
times_.pop();
- times_.push(stopwatch_.Elapsed());
+ times_.push(time_millis_);
if (times_.back() != times_.front())
- rate_ = times_.size() / (times_.back() - times_.front());
+ rate_ = times_.size() / ((times_.back() - times_.front()) / 1e3);
}
private:
double rate_;
- Stopwatch stopwatch_;
const size_t N;
std::queue<double> times_;
int last_update_;
};
- mutable RateInfo overall_rate_;
mutable SlidingRateInfo current_rate_;
};
diff --git a/src/build_test.cc b/src/build_test.cc
index 0baabc4..4ccb2c4 100644
--- a/src/build_test.cc
+++ b/src/build_test.cc
@@ -486,13 +486,13 @@
struct BuildTest : public StateTestWithBuiltinRules, public BuildLogUser {
BuildTest() : config_(MakeConfig()), command_runner_(&fs_),
- builder_(&state_, config_, NULL, NULL, &fs_),
+ builder_(&state_, config_, NULL, NULL, &fs_, 0),
status_(config_) {
}
explicit BuildTest(DepsLog* log)
: config_(MakeConfig()), command_runner_(&fs_),
- builder_(&state_, config_, NULL, log, &fs_), status_(config_) {}
+ builder_(&state_, config_, NULL, log, &fs_, 0), status_(config_) {}
virtual void SetUp() {
StateTestWithBuiltinRules::SetUp();
@@ -563,7 +563,7 @@
pdeps_log = &deps_log;
}
- Builder builder(pstate, config_, pbuild_log, pdeps_log, &fs_);
+ Builder builder(pstate, config_, pbuild_log, pdeps_log, &fs_, 0);
EXPECT_TRUE(builder.AddTarget(target, &err));
command_runner_.commands_ran_.clear();
@@ -1400,7 +1400,7 @@
ASSERT_EQ("", err);
EXPECT_TRUE(builder_.Build(&err));
ASSERT_EQ("", err);
- EXPECT_EQ("[3/3]", builder_.status_->FormatProgressStatus("[%s/%t]",
+ EXPECT_EQ("[3/3]", builder_.status_->FormatProgressStatus("[%s/%t]", 0,
BuildStatus::kEdgeStarted));
command_runner_.commands_ran_.clear();
state_.Reset();
@@ -1843,13 +1843,13 @@
status_.BuildStarted();
// Before any task is done, the elapsed time must be zero.
EXPECT_EQ("[%/e0.000]",
- status_.FormatProgressStatus("[%%/e%e]",
+ status_.FormatProgressStatus("[%%/e%e]", 0,
BuildStatus::kEdgeStarted));
}
TEST_F(BuildTest, StatusFormatReplacePlaceholder) {
EXPECT_EQ("[%/s0/t0/r0/u0/f0]",
- status_.FormatProgressStatus("[%%/s%s/t%t/r%r/u%u/f%f]",
+ status_.FormatProgressStatus("[%%/s%s/t%t/r%r/u%u/f%f]", 0,
BuildStatus::kEdgeStarted));
}
@@ -2120,7 +2120,7 @@
ASSERT_TRUE(deps_log.OpenForWrite("ninja_deps", &err));
ASSERT_EQ("", err);
- Builder builder(&state, config_, NULL, &deps_log, &fs_);
+ Builder builder(&state, config_, NULL, &deps_log, &fs_, 0);
builder.command_runner_.reset(&command_runner_);
EXPECT_TRUE(builder.AddTarget("out", &err));
ASSERT_EQ("", err);
@@ -2150,7 +2150,7 @@
ASSERT_TRUE(deps_log.Load("ninja_deps", &state, &err));
ASSERT_TRUE(deps_log.OpenForWrite("ninja_deps", &err));
- Builder builder(&state, config_, NULL, &deps_log, &fs_);
+ Builder builder(&state, config_, NULL, &deps_log, &fs_, 0);
builder.command_runner_.reset(&command_runner_);
command_runner_.commands_ran_.clear();
EXPECT_TRUE(builder.AddTarget("out", &err));
@@ -2191,7 +2191,7 @@
ASSERT_TRUE(deps_log.OpenForWrite("ninja_deps", &err));
ASSERT_EQ("", err);
- Builder builder(&state, config_, NULL, &deps_log, &fs_);
+ Builder builder(&state, config_, NULL, &deps_log, &fs_, 0);
builder.command_runner_.reset(&command_runner_);
EXPECT_TRUE(builder.AddTarget("out", &err));
ASSERT_EQ("", err);
@@ -2220,7 +2220,7 @@
ASSERT_TRUE(deps_log.Load("ninja_deps", &state, &err));
ASSERT_TRUE(deps_log.OpenForWrite("ninja_deps", &err));
- Builder builder(&state, config_, NULL, &deps_log, &fs_);
+ Builder builder(&state, config_, NULL, &deps_log, &fs_, 0);
builder.command_runner_.reset(&command_runner_);
command_runner_.commands_ran_.clear();
EXPECT_TRUE(builder.AddTarget("out", &err));
@@ -2256,7 +2256,7 @@
// The deps log is NULL in dry runs.
config_.dry_run = true;
- Builder builder(&state, config_, NULL, NULL, &fs_);
+ Builder builder(&state, config_, NULL, NULL, &fs_, 0);
builder.command_runner_.reset(&command_runner_);
command_runner_.commands_ran_.clear();
@@ -2314,7 +2314,7 @@
ASSERT_TRUE(deps_log.OpenForWrite("ninja_deps", &err));
ASSERT_EQ("", err);
- Builder builder(&state, config_, NULL, &deps_log, &fs_);
+ Builder builder(&state, config_, NULL, &deps_log, &fs_, 0);
builder.command_runner_.reset(&command_runner_);
EXPECT_TRUE(builder.AddTarget("out", &err));
ASSERT_EQ("", err);
@@ -2340,7 +2340,7 @@
ASSERT_TRUE(deps_log.Load("ninja_deps", &state, &err));
ASSERT_TRUE(deps_log.OpenForWrite("ninja_deps", &err));
- Builder builder(&state, config_, NULL, &deps_log, &fs_);
+ Builder builder(&state, config_, NULL, &deps_log, &fs_, 0);
builder.command_runner_.reset(&command_runner_);
command_runner_.commands_ran_.clear();
EXPECT_TRUE(builder.AddTarget("out", &err));
@@ -2373,7 +2373,7 @@
ASSERT_TRUE(deps_log.OpenForWrite("ninja_deps", &err));
ASSERT_EQ("", err);
- Builder builder(&state, config_, NULL, &deps_log, &fs_);
+ Builder builder(&state, config_, NULL, &deps_log, &fs_, 0);
builder.command_runner_.reset(&command_runner_);
EXPECT_TRUE(builder.AddTarget("fo o.o", &err));
ASSERT_EQ("", err);
@@ -2394,7 +2394,7 @@
ASSERT_TRUE(deps_log.OpenForWrite("ninja_deps", &err));
ASSERT_EQ("", err);
- Builder builder(&state, config_, NULL, &deps_log, &fs_);
+ Builder builder(&state, config_, NULL, &deps_log, &fs_, 0);
builder.command_runner_.reset(&command_runner_);
Edge* edge = state.edges_.back();
@@ -2435,7 +2435,7 @@
ASSERT_TRUE(deps_log.OpenForWrite("ninja_deps", &err));
ASSERT_EQ("", err);
- Builder builder(&state, config_, NULL, &deps_log, &fs_);
+ Builder builder(&state, config_, NULL, &deps_log, &fs_, 0);
builder.command_runner_.reset(&command_runner_);
EXPECT_TRUE(builder.AddTarget("a/b/c/d/e/fo o.o", &err));
ASSERT_EQ("", err);
@@ -2458,7 +2458,7 @@
ASSERT_TRUE(deps_log.OpenForWrite("ninja_deps", &err));
ASSERT_EQ("", err);
- Builder builder(&state, config_, NULL, &deps_log, &fs_);
+ Builder builder(&state, config_, NULL, &deps_log, &fs_, 0);
builder.command_runner_.reset(&command_runner_);
Edge* edge = state.edges_.back();
diff --git a/src/ninja.cc b/src/ninja.cc
index eb97320..57690be 100644
--- a/src/ninja.cc
+++ b/src/ninja.cc
@@ -82,7 +82,8 @@
/// to poke into these, so store them as fields on an object.
struct NinjaMain : public BuildLogUser {
NinjaMain(const char* ninja_command, const BuildConfig& config) :
- ninja_command_(ninja_command), config_(config) {}
+ ninja_command_(ninja_command), config_(config),
+ start_time_millis_(GetTimeMillis()) {}
/// Command line used to run Ninja.
const char* ninja_command_;
@@ -172,6 +173,8 @@
Error("%s", err.c_str()); // Log and ignore Stat() errors.
return mtime == 0;
}
+
+ int64_t start_time_millis_;
};
/// Subtools, accessible via "-t foo".
@@ -249,7 +252,8 @@
if (!node)
return false;
- Builder builder(&state_, config_, &build_log_, &deps_log_, &disk_interface_);
+ Builder builder(&state_, config_, &build_log_, &deps_log_, &disk_interface_,
+ start_time_millis_);
if (!builder.AddTarget(node, err))
return false;
@@ -1199,7 +1203,8 @@
disk_interface_.AllowStatCache(g_experimental_statcache);
- Builder builder(&state_, config_, &build_log_, &deps_log_, &disk_interface_);
+ Builder builder(&state_, config_, &build_log_, &deps_log_, &disk_interface_,
+ start_time_millis_);
for (size_t i = 0; i < targets.size(); ++i) {
if (!builder.AddTarget(targets[i], &err)) {
if (!err.empty()) {
