diff options
-rw-r--r-- | src/build.cc | 79 | ||||
-rw-r--r-- | src/build.h | 54 | ||||
-rw-r--r-- | src/build_test.cc | 34 | ||||
-rw-r--r-- | src/ninja.cc | 11 |
4 files changed, 80 insertions, 98 deletions
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 @@ bool DryRunCommandRunner::WaitForCommand(Result* result) { } // 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 @@ void BuildStatus::PlanHasTotalEdges(int total) { 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 @@ void BuildStatus::BuildEdgeFinished(Edge* edge, 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::BuildLoadDyndeps() { } void BuildStatus::BuildStarted() { - overall_rate_.Restart(); - current_rate_.Restart(); } void BuildStatus::BuildFinished() { @@ -202,10 +193,9 @@ void BuildStatus::BuildFinished() { } 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 @@ string BuildStatus::FormatProgressStatus( // 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 @@ string BuildStatus::FormatProgressStatus( 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 @@ void BuildStatus::PrintStatus(const Edge* edge, EdgeStatus status) { 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 @@ bool RealCommandRunner::WaitForCommand(Result* result) { 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 @@ bool Builder::StartEdge(Edge* edge, string* err) { 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 @@ bool Builder::FinishCommand(CommandRunner::Result* result, string* err) { } } - 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 @@ bool Builder::FinishCommand(CommandRunner::Result* result, string* err) { 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 BuildConfig { 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 @@ struct Builder { 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 Builder { 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 @@ struct BuildStatus { /// @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 @@ struct BuildStatus { 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 FakeCommandRunner : public CommandRunner { 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 @@ void BuildTest::RebuildTarget(const string& target, const char* manifest, 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 @@ TEST_F(BuildWithLogTest, RestatTest) { 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 @@ TEST_F(BuildTest, StatusFormatElapsed) { 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 @@ TEST_F(BuildWithDepsLogTest, Straightforward) { 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 @@ TEST_F(BuildWithDepsLogTest, Straightforward) { 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 @@ TEST_F(BuildWithDepsLogTest, ObsoleteDeps) { 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 @@ TEST_F(BuildWithDepsLogTest, ObsoleteDeps) { 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 @@ TEST_F(BuildWithDepsLogTest, DepsIgnoredInDryRun) { // 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 @@ TEST_F(BuildWithDepsLogTest, RestatDepfileDependencyDepsLog) { 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 @@ TEST_F(BuildWithDepsLogTest, RestatDepfileDependencyDepsLog) { 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 @@ TEST_F(BuildWithDepsLogTest, DepFileOKDepsLog) { 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 @@ TEST_F(BuildWithDepsLogTest, DepFileOKDepsLog) { 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 @@ TEST_F(BuildWithDepsLogTest, DepFileDepsLogCanonicalize) { 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 @@ TEST_F(BuildWithDepsLogTest, DepFileDepsLogCanonicalize) { 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 @@ struct Options { /// 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 @@ struct NinjaMain : public BuildLogUser { 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 @@ bool NinjaMain::RebuildManifest(const char* input_file, string* err) { 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 @@ int NinjaMain::RunBuild(int argc, char** argv) { 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()) { |