add a versioning header to build log, switch to v2

In v2 we store both the start and end time of the command.
This allows better visualization of the build process.

4 files changed, 83 insertions, 27 deletions

diff --git a/src/build.cc b/src/build.cc
index 7f7ae6d..1deb08a 100644
--- a/src/build.cc
+++ b/src/build.cc
@@ -49,15 +49,19 @@ struct BuildStatus {
   BuildStatus();
   void PlanHasTotalEdges(int total);
   void BuildEdgeStarted(Edge* edge);
-  /// Returns the time the edge took, in ms.
-  int BuildEdgeFinished(Edge* edge);
+  void BuildEdgeFinished(Edge* edge, int* start_time, int* end_time);
 
   void PrintStatus(Edge* edge);
 
+  /// Time the build started.
+  int64_t start_time_millis_;
+  /// Time we last printed an update.
   int64_t last_update_millis_;
+
   int finished_edges_, total_edges_;
 
-  typedef map<Edge*, int64_t> RunningEdgeMap;
+  /// Map of running edge to time the edge started running.
+  typedef map<Edge*, int> RunningEdgeMap;
   RunningEdgeMap running_edges_;
 
   BuildConfig::Verbosity verbosity_;
@@ -66,7 +70,8 @@ struct BuildStatus {
 };
 
 BuildStatus::BuildStatus()
-    : last_update_millis_(GetTimeMillis()),
+    : start_time_millis_(GetTimeMillis()),
+      last_update_millis_(start_time_millis_),
       finished_edges_(0), total_edges_(0),
       verbosity_(BuildConfig::NORMAL) {
 #ifndef WIN32
@@ -82,12 +87,15 @@ void BuildStatus::PlanHasTotalEdges(int total) {
 }
 
 void BuildStatus::BuildEdgeStarted(Edge* edge) {
-  running_edges_.insert(make_pair(edge, GetTimeMillis()));
+  int start_time = (int)(GetTimeMillis() - start_time_millis_);
+  running_edges_.insert(make_pair(edge, start_time));
 
   PrintStatus(edge);
 }
 
-int BuildStatus::BuildEdgeFinished(Edge* edge) {
+void BuildStatus::BuildEdgeFinished(Edge* edge,
+                                    int* start_time,
+                                    int* end_time) {
   int64_t now = GetTimeMillis();
   ++finished_edges_;
 
@@ -106,10 +114,9 @@ int BuildStatus::BuildEdgeFinished(Edge* edge) {
   }
 
   RunningEdgeMap::iterator i = running_edges_.find(edge);
-  int ms = (int)(now - i->second);
+  *start_time = i->second;
+  *end_time = (int)(now - start_time_millis_);
   running_edges_.erase(i);
-
-  return ms;
 }
 
 void BuildStatus::PrintStatus(Edge* edge) {
@@ -487,7 +494,8 @@ void Builder::FinishEdge(Edge* edge) {
   if (edge->is_phony())
     return;
 
-  int ms = status_->BuildEdgeFinished(edge);
+  int start_time, end_time;
+  status_->BuildEdgeFinished(edge, &start_time, &end_time);
   if (log_)
-    log_->RecordCommand(edge, ms);
+    log_->RecordCommand(edge, start_time, end_time);
 }
diff --git a/src/build_log.cc b/src/build_log.cc
index 66b85a9..cd74bd1 100644
--- a/src/build_log.cc
+++ b/src/build_log.cc
@@ -29,6 +29,13 @@
 // Once the number of redundant entries exceeds a threshold, we write
 // out a new file and replace the existing one with it.
 
+namespace {
+
+const char kFileSignature[] = "# ninja log v2\n";
+const int kCurrentVersion = 2;
+
+}
+
 BuildLog::BuildLog()
   : log_file_(NULL), config_(NULL), needs_recompaction_(false) {}
 
@@ -48,10 +55,18 @@ bool BuildLog::OpenForWrite(const string& path, string* err) {
     return false;
   }
   setvbuf(log_file_, NULL, _IOLBF, 0);
+
+  if (ftell(log_file_) == 0) {
+    if (fwrite(kFileSignature, sizeof(kFileSignature) - 1, 1, log_file_) < 1) {
+      *err = strerror(errno);
+      return false;
+    }
+  }
+
   return true;
 }
 
-void BuildLog::RecordCommand(Edge* edge, int time_ms) {
+void BuildLog::RecordCommand(Edge* edge, int start_time, int end_time) {
   if (!log_file_)
     return;
 
@@ -69,7 +84,8 @@ void BuildLog::RecordCommand(Edge* edge, int time_ms) {
     }
     log_entry->output = path;
     log_entry->command = command;
-    log_entry->time_ms = time_ms;
+    log_entry->start_time = start_time;
+    log_entry->end_time = end_time;
 
     WriteEntry(log_file_, *log_entry);
   }
@@ -90,19 +106,43 @@ bool BuildLog::Load(const string& path, string* err) {
     return false;
   }
 
+  int log_version = 0;
   int unique_entry_count = 0;
   int total_entry_count = 0;
 
   char buf[256 << 10];
   while (fgets(buf, sizeof(buf), file)) {
+    if (!log_version) {
+      log_version = 1;  // Assume by default.
+      if (strcmp(buf, kFileSignature) == 0) {
+        log_version = 2;
+        continue;
+      }
+    }
     char* start = buf;
     char* end = strchr(start, ' ');
     if (!end)
       continue;
-
     *end = 0;
-    int time_ms = atoi(start);
-    start = end + 1;
+
+    int start_time = 0, end_time = 0;
+    if (log_version == 1) {
+      // In v1 we logged how long the command took; we don't use this info.
+      // int time_ms = atoi(start);
+      start = end + 1;
+    } else {
+      // In v2 we log the start time and the end time.
+      start_time = atoi(start);
+      start = end + 1;
+
+      char* end = strchr(start, ' ');
+      if (!end)
+        continue;
+      *end = 0;
+      end_time = atoi(start);
+      start = end + 1;
+    }
+
     end = strchr(start, ' ');
     string output = string(start, end - start);
 
@@ -117,8 +157,9 @@ bool BuildLog::Load(const string& path, string* err) {
     }
     ++total_entry_count;
 
-    entry->time_ms = time_ms;
     entry->output = output;
+    entry->start_time = start_time;
+    entry->end_time = end_time;
 
     start = end + 1;
     end = strchr(start, '\n');
@@ -126,10 +167,12 @@ bool BuildLog::Load(const string& path, string* err) {
   }
 
   // Mark the log as "needs rebuiding" if it has kCompactionRatio times
-  // too many log entries.
+  // too many log entries or it's the wrong version.
   int kCompactionRatio = 3;
-  if (total_entry_count > unique_entry_count * kCompactionRatio)
+  if (total_entry_count > unique_entry_count * kCompactionRatio ||
+      log_version < kCurrentVersion) {
     needs_recompaction_ = true;
+  }
 
   fclose(file);
 
@@ -144,8 +187,9 @@ BuildLog::LogEntry* BuildLog::LookupByOutput(const string& path) {
 }
 
 void BuildLog::WriteEntry(FILE* f, const LogEntry& entry) {
-  fprintf(f, "%d %s %s\n",
-          entry.time_ms, entry.output.c_str(), entry.command.c_str());
+  fprintf(f, "%d %d %s %s\n",
+          entry.start_time, entry.end_time,
+          entry.output.c_str(), entry.command.c_str());
 }
 
 bool BuildLog::Recompact(const string& path, string* err) {
diff --git a/src/build_log.h b/src/build_log.h
index 5d8d6a2..81a745f 100644
--- a/src/build_log.h
+++ b/src/build_log.h
@@ -35,7 +35,7 @@ struct BuildLog {
 
   void SetConfig(BuildConfig* config) { config_ = config; }
   bool OpenForWrite(const string& path, string* err);
-  void RecordCommand(Edge* edge, int time_ms);
+  void RecordCommand(Edge* edge, int start_time, int end_time);
   void Close();
 
   /// Load the on-disk log.
@@ -44,9 +44,13 @@ struct BuildLog {
   struct LogEntry {
     string output;
     string command;
-    int time_ms;
+    int start_time;
+    int end_time;
+
+    // Used by tests.
     bool operator==(const LogEntry& o) {
-      return output == o.output && command == o.command && time_ms == o.time_ms;
+      return output == o.output && command == o.command &&
+          start_time == o.start_time && end_time == o.end_time;
     }
   };
 
diff --git a/src/build_log_test.cc b/src/build_log_test.cc
index 66f88c3..caf1540 100644
--- a/src/build_log_test.cc
+++ b/src/build_log_test.cc
@@ -35,8 +35,8 @@ TEST_F(BuildLogTest, WriteRead) {
   string err;
   EXPECT_TRUE(log1.OpenForWrite(kTestFilename, &err));
   ASSERT_EQ("", err);
-  log1.RecordCommand(state_.edges_[0], 15);
-  log1.RecordCommand(state_.edges_[1], 20);
+  log1.RecordCommand(state_.edges_[0], 15, 18);
+  log1.RecordCommand(state_.edges_[1], 20, 25);
   log1.Close();
 
   BuildLog log2;
@@ -50,7 +50,7 @@ TEST_F(BuildLogTest, WriteRead) {
   BuildLog::LogEntry* e2 = log2.LookupByOutput("out");
   ASSERT_TRUE(e2);
   ASSERT_TRUE(*e1 == *e2);
-  ASSERT_EQ(15, e1->time_ms);
+  ASSERT_EQ(15, e1->start_time);
   ASSERT_EQ("out", e1->output);
 }