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.

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()) {