Record the start time of each output's command in the build log

When an edge starts to run, create a temporary file in the target
directory of the first output file, stat it, and cache its mtime. When
the command finishes, use the cached temporary file's mtime from when
the edge started running as the mtime that is recorded in the build log
for each of the edge's output(s). Subsequent runs will use that as the
mtime for the output(s).

This provides robustness against inputs changing while the command
itself is running. If an input is changed, the subsequent run will
detect the output as dirty since its recorded mtime reflects when the
build command began, not when the output was actually written to disk.

Generator rules are exempt from this and will continue to record their
actual mtime on disk at the time the command finished in the build log.
This avoids potential infinite loops when the generator rule touches
input dependencies of the output(s).

src/build.cc

@@ -679,14 +679,33 @@ bool Builder::StartEdge(Edge* edge, string* err) {
 
   status_->BuildEdgeStarted(edge, start_time_millis);
 
-  // Create directories necessary for outputs.
+  TimeStamp build_start = -1;
+
+  // Create directories necessary for outputs and remember the current
+  // filesystem mtime to record later
   // XXX: this will block; do we care?
   for (vector<Node*>::iterator o = edge->outputs_.begin();
        o != edge->outputs_.end(); ++o) {
     if (!disk_interface_->MakeDirs((*o)->path()))
       return false;
+    if (build_start == -1) {
+      string tmp_path = DirName((*o)->PathDecanonicalized(), true) + ".ninja_tmp";
+      if (!disk_interface_->WriteFile(tmp_path, "")) {
+        err->assign("could not create temporary file to determine command "
+                    "start time of '" + edge->EvaluateCommand() + "'");
+        return false;
+      }
+
+      build_start = disk_interface_->Stat(tmp_path, err);
+      disk_interface_->RemoveFile(tmp_path);
+
+      if (build_start == -1)
+        return false;
+    }
   }
 
+  edge->command_start_time_ = build_start;
+
   // Create response file, if needed
   // XXX: this may also block; do we care?
   string rspfile = edge->GetUnescapedRspfile();
@@ -745,18 +764,20 @@ bool Builder::FinishCommand(CommandRunner::Result* result, string* err) {
   }
 
   // Restat the edge outputs
-  TimeStamp output_mtime = 0;
-  bool restat = edge->GetBindingBool("restat");
+  TimeStamp record_mtime = 0;
   if (!config_.dry_run) {
+    bool const restat = edge->GetBindingBool("restat");
+    bool const generator = edge->GetBindingBool("generator");
     bool node_cleaned = false;
 
+    record_mtime = edge->command_start_time_;
     for (vector<Node*>::iterator o = edge->outputs_.begin();
          o != edge->outputs_.end(); ++o) {
       TimeStamp new_mtime = disk_interface_->Stat((*o)->path(), err);
       if (new_mtime == -1)
         return false;
-      if (new_mtime > output_mtime)
-        output_mtime = new_mtime;
+      if (new_mtime > record_mtime && generator)
+        record_mtime = new_mtime;
       if ((*o)->mtime() == new_mtime && restat) {
         // The rule command did not change the output.  Propagate the clean
         // state through the build graph.
@@ -766,34 +787,10 @@ bool Builder::FinishCommand(CommandRunner::Result* result, string* err) {
         node_cleaned = true;
       }
     }
-
     if (node_cleaned) {
-      TimeStamp restat_mtime = 0;
-      // If any output was cleaned, find the most recent mtime of any
-      // (existing) non-order-only input or the depfile.
-      for (vector<Node*>::iterator i = edge->inputs_.begin();
-           i != edge->inputs_.end() - edge->order_only_deps_; ++i) {
-        TimeStamp input_mtime = disk_interface_->Stat((*i)->path(), err);
-        if (input_mtime == -1)
-          return false;
-        if (input_mtime > restat_mtime)
-          restat_mtime = input_mtime;
-      }
-
-      string depfile = edge->GetUnescapedDepfile();
-      if (restat_mtime != 0 && deps_type.empty() && !depfile.empty()) {
-        TimeStamp depfile_mtime = disk_interface_->Stat(depfile, err);
-        if (depfile_mtime == -1)
-          return false;
-        if (depfile_mtime > restat_mtime)
-          restat_mtime = depfile_mtime;
-      }
-
       // The total number of edges in the plan may have changed as a result
       // of a restat.
       status_->PlanHasTotalEdges(plan_.command_edge_count());
-
-      output_mtime = restat_mtime;
     }
   }
 
@@ -807,7 +804,7 @@ bool Builder::FinishCommand(CommandRunner::Result* result, string* err) {
 
   if (scan_.build_log()) {
     if (!scan_.build_log()->RecordCommand(edge, start_time_millis,
-                                          end_time_millis, output_mtime)) {
+                                          end_time_millis, record_mtime)) {
       *err = string("Error writing to build log: ") + strerror(errno);
       return false;
     }

src/build_log.cc

@@ -116,9 +116,9 @@ BuildLog::LogEntry::LogEntry(const string& output)
   : output(output) {}
 
 BuildLog::LogEntry::LogEntry(const string& output, uint64_t command_hash,
-  int start_time, int end_time, TimeStamp restat_mtime)
+  int start_time, int end_time, TimeStamp mtime)
   : output(output), command_hash(command_hash),
-    start_time(start_time), end_time(end_time), mtime(restat_mtime)
+    start_time(start_time), end_time(end_time), mtime(mtime)
 {}
 
 BuildLog::BuildLog()
@@ -303,7 +303,7 @@ LoadStatus BuildLog::Load(const string& path, string* err) {
     *end = 0;
 
     int start_time = 0, end_time = 0;
-    TimeStamp restat_mtime = 0;
+    TimeStamp mtime = 0;
 
     start_time = atoi(start);
     start = end + 1;
@@ -319,7 +319,7 @@ LoadStatus BuildLog::Load(const string& path, string* err) {
     if (!end)
       continue;
     *end = 0;
-    restat_mtime = strtoll(start, NULL, 10);
+    mtime = strtoll(start, NULL, 10);
     start = end + 1;
 
     end = (char*)memchr(start, kFieldSeparator, line_end - start);
@@ -343,7 +343,7 @@ LoadStatus BuildLog::Load(const string& path, string* err) {
 
     entry->start_time = start_time;
     entry->end_time = end_time;
-    entry->mtime = restat_mtime;
+    entry->mtime = mtime;
     if (log_version >= 5) {
       char c = *end; *end = '\0';
       entry->command_hash = (uint64_t)strtoull(start, NULL, 16);

src/build_log.h

@@ -73,7 +73,7 @@ struct BuildLog {
 
     explicit LogEntry(const std::string& output);
     LogEntry(const std::string& output, uint64_t command_hash,
-             int start_time, int end_time, TimeStamp restat_mtime);
+             int start_time, int end_time, TimeStamp mtime);
   };
 
   /// Lookup a previously-run command by its output path.