add a class for logging builds (commands + timing)

5 files changed, 179 insertions, 5 deletions

diff --git a/build.ninja b/build.ninja
index 29d6237..c650cd2 100644
--- a/build.ninja
+++ b/build.ninja
@@ -29,22 +29,26 @@ rule link
 # build "ninja.a" by linking the builddir's "ninja.o",
 # and build that "ninja.o" by compiling "ninja.cc".
 build $builddir/build.o: cxx src/build.cc
+build $builddir/build_log.o: cxx src/build_log.cc
 build $builddir/parsers.o: cxx src/parsers.cc
 build $builddir/subprocess.o: cxx src/subprocess.cc
 build $builddir/util.o: cxx src/util.cc
 build $builddir/ninja_jumble.o: cxx src/ninja_jumble.cc
-build $builddir/ninja.a: ar $builddir/build.o $builddir/parsers.o \
-    $builddir/subprocess.o $builddir/util.o $builddir/ninja_jumble.o
+build $builddir/ninja.a: ar $builddir/build.o $builddir/build_log.o \
+    $builddir/parsers.o $builddir/subprocess.o $builddir/util.o \
+    $builddir/ninja_jumble.o
 
 build $builddir/ninja.o: cxx src/ninja.cc
 build ninja: link $builddir/ninja.o $builddir/ninja.a
 
 build $builddir/build_test.o: cxx src/build_test.cc
+build $builddir/build_log_test.o: cxx src/build_log_test.cc
 build $builddir/ninja_test.o: cxx src/ninja_test.cc
 build $builddir/parsers_test.o: cxx src/parsers_test.cc
 build $builddir/subprocess_test.o: cxx src/subprocess_test.cc
-build ninja_test: link $builddir/build_test.o $builddir/ninja_test.o \
-    $builddir/parsers_test.o $builddir/subprocess_test.o $builddir/ninja.a
+build ninja_test: link $builddir/build_test.o $builddir/build_log_test.o \
+    $builddir/ninja_test.o $builddir/parsers_test.o \
+    $builddir/subprocess_test.o $builddir/ninja.a
   ldflags = -g -rdynamic -lgtest -lgtest_main -lpthread
 
 
diff --git a/src/build_log.cc b/src/build_log.cc
new file mode 100644
index 0000000..06db0e6
--- /dev/null
+++ b/src/build_log.cc
@@ -0,0 +1,89 @@
+#include "build_log.h"
+
+#include <errno.h>
+#include <stdio.h>
+#include <string.h>
+
+#include "ninja.h"
+
+// Implementation details:
+// Each run's log appends to the log file.
+// To load, we run through all log entries in series, throwing away
+// older runs.
+// XXX figure out recompaction strategy
+
+bool BuildLog::OpenForWrite(const string& path, string* err) {
+  log_file_ = fopen(path.c_str(), "ab");
+  if (!log_file_) {
+    *err = strerror(errno);
+    return false;
+  }
+  setlinebuf(log_file_);
+  return true;
+}
+
+void BuildLog::RecordCommand(Edge* edge, int time_ms) {
+  const string command = edge->EvaluateCommand();
+  for (vector<Node*>::iterator out = edge->outputs_.begin();
+       out != edge->outputs_.end(); ++out) {
+    const string& path = (*out)->file_->path_;
+    Log::iterator i = log_.find(path);
+    LogEntry* log_entry;
+    if (i != log_.end()) {
+      log_entry = i->second;
+    } else {
+      log_entry = new LogEntry;
+      log_.insert(make_pair(path, log_entry));
+    }
+    log_entry->output = path;
+    log_entry->command = command;
+    log_entry->time_ms = time_ms;
+
+    fprintf(log_file_, "%d %s %s\n", time_ms, path.c_str(), command.c_str());
+  }
+}
+
+void BuildLog::Close() {
+  fclose(log_file_);
+  log_file_ = NULL;
+}
+
+// Load the on-disk log.
+bool BuildLog::Load(const string& path, string* err) {
+  FILE* file = fopen(path.c_str(), "r");
+  if (!file) {
+    *err = strerror(errno);
+    return false;
+  }
+
+  char buf[4 << 10];
+  while (fgets(buf, sizeof(buf), file)) {
+    char* start = buf;
+    char* end = strchr(start, ' ');
+    if (!end)
+      continue;
+
+    LogEntry* entry = new LogEntry;
+    *end = 0;
+    entry->time_ms = atoi(start);
+
+    start = end + 1;
+    end = strchr(start, ' ');
+    entry->output = string(start, end - start);
+
+    start = end + 1;
+    end = strchr(start, '\n');
+    entry->command = string(start, end - start);
+    log_.insert(make_pair(entry->output, entry));
+  }
+
+  return true;
+}
+
+// Lookup a previously-run command by its output path.
+BuildLog::LogEntry* BuildLog::LookupByOutput(const string& path) {
+  Log::iterator i = log_.find(path);
+  if (i != log_.end())
+    return i->second;
+  return NULL;
+}
diff --git a/src/build_log.h b/src/build_log.h
new file mode 100644
index 0000000..1d9463c
--- /dev/null
+++ b/src/build_log.h
@@ -0,0 +1,37 @@
+#include <map>
+#include <string>
+using namespace std;
+
+struct Edge;
+
+// Store a log of every command ran for every build.
+// It has a few uses:
+// 1) historical command lines for output files, so we know
+//    when we need to rebuild due to the command changing
+// 2) historical timing information
+// 3) maybe we can generate some sort of build overview output
+//    from it
+struct BuildLog {
+  bool OpenForWrite(const string& path, string* err);
+  void RecordCommand(Edge* edge, int time_ms);
+  void Close();
+
+  // Load the on-disk log.
+  bool Load(const string& path, string* err);
+
+  struct LogEntry {
+    string output;
+    string command;
+    int time_ms;
+    bool operator==(const LogEntry& o) {
+      return output == o.output && command == o.command && time_ms == o.time_ms;
+    }
+  };
+
+  // Lookup a previously-run command by its output path.
+  LogEntry* LookupByOutput(const string& path);
+
+  typedef map<string, LogEntry*> Log;
+  Log log_;
+  FILE* log_file_;
+};
diff --git a/src/build_log_test.cc b/src/build_log_test.cc
new file mode 100644
index 0000000..6807a04
--- /dev/null
+++ b/src/build_log_test.cc
@@ -0,0 +1,43 @@
+#include "build_log.h"
+
+#include "test.h"
+
+struct BuildLogTest : public StateTestWithBuiltinRules {
+  virtual void SetUp() {
+    char mktemp_template[] = "BuildLogTest-XXXXXX";
+    log_filename_ = mktemp(mktemp_template);
+  }
+  virtual void TearDown() {
+    unlink(log_filename_.c_str());
+  }
+
+  string log_filename_;
+};
+
+TEST_F(BuildLogTest, WriteRead) {
+  AssertParse(&state_,
+"build out: cat mid\n"
+"build mid: cat in\n");
+
+  BuildLog log1;
+  string err;
+  EXPECT_TRUE(log1.OpenForWrite(log_filename_, &err));
+  ASSERT_EQ("", err);
+  log1.RecordCommand(state_.edges_[0], 15);
+  log1.RecordCommand(state_.edges_[1], 20);
+  log1.Close();
+
+  BuildLog log2;
+  EXPECT_TRUE(log2.Load(log_filename_, &err));
+  ASSERT_EQ("", err);
+
+  ASSERT_EQ(2, log1.log_.size());
+  ASSERT_EQ(2, log2.log_.size());
+  BuildLog::LogEntry* e1 = log1.LookupByOutput("out");
+  ASSERT_TRUE(e1);
+  BuildLog::LogEntry* e2 = log2.LookupByOutput("out");
+  ASSERT_TRUE(e2);
+  ASSERT_TRUE(*e1 == *e2);
+  ASSERT_EQ(15, e1->time_ms);
+  ASSERT_EQ("out", e1->output);
+}
diff --git a/todo b/todo
index ad1b3c7..e24410f 100644
--- a/todo
+++ b/todo
@@ -1,5 +1,6 @@
 save command lines
-  or use mtimes on build files?
+collect per-command timing, perhaps saving with command lines
+
 "explain" mode that shows why we're building a file
 "one file" mode that builds only outputs of a single file
 adjust to system load dynamically