When an edge starts to build, create a temporary file and remember it…

…s mtime

When recording the outputs' mtimes when the command finishes, use the
remembered temporary file's mtime from when the edge started for
recording in the build log. Subsequent runs will use that as the mtime
for the output.

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.

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,55 +764,29 @@ bool Builder::FinishCommand(CommandRunner::Result* result, string* err) {
   }
 
   // Restat the edge outputs
-  TimeStamp output_mtime = 0;
-  bool restat = edge->GetBindingBool("restat");
   if (!config_.dry_run) {
     bool node_cleaned = false;
 
-    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 ((*o)->mtime() == new_mtime && restat) {
-        // The rule command did not change the output.  Propagate the clean
-        // state through the build graph.
-        // Note that this also applies to nonexistent outputs (mtime == 0).
-        if (!plan_.CleanNode(&scan_, *o, err))
-          return false;
-        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)
+    if (edge->GetBindingBool("restat")) {
+      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 (input_mtime > restat_mtime)
-          restat_mtime = input_mtime;
+        if ((*o)->mtime() == new_mtime) {
+          // The rule command did not change the output.  Propagate the clean
+          // state through the build graph.
+          // Note that this also applies to nonexistent outputs (mtime == 0).
+          if (!plan_.CleanNode(&scan_, *o, err))
+            return false;
+          node_cleaned = true;
+        }
       }
-
-      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;
+      if (node_cleaned) {
+        // The total number of edges in the plan may have changed as a result
+        // of a restat.
+        status_->PlanHasTotalEdges(plan_.command_edge_count());
       }
-
-      // 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;
     }
   }
 
@@ -806,8 +799,7 @@ bool Builder::FinishCommand(CommandRunner::Result* result, string* err) {
     disk_interface_->RemoveFile(rspfile);
 
   if (scan_.build_log()) {
-    if (!scan_.build_log()->RecordCommand(edge, start_time_millis,
-                                          end_time_millis, output_mtime)) {
+    if (!scan_.build_log()->RecordCommand(edge, start_time_millis, end_time_millis)) {
       *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()
@@ -141,8 +141,7 @@ bool BuildLog::OpenForWrite(const string& path, const BuildLogUser& user,
   return true;
 }
 
-bool BuildLog::RecordCommand(Edge* edge, int start_time, int end_time,
-                             TimeStamp mtime) {
+bool BuildLog::RecordCommand(Edge* edge, int start_time, int end_time) {
   string command = edge->EvaluateCommand(true);
   uint64_t command_hash = LogEntry::HashCommand(command);
   for (vector<Node*>::iterator out = edge->outputs_.begin();
@@ -159,7 +158,7 @@ bool BuildLog::RecordCommand(Edge* edge, int start_time, int end_time,
     log_entry->command_hash = command_hash;
     log_entry->start_time = start_time;
     log_entry->end_time = end_time;
-    log_entry->mtime = mtime;
+    log_entry->mtime = edge->command_start_time_;
 
     if (!OpenForWriteIfNeeded()) {
       return false;
@@ -303,7 +302,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 +318,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 +342,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

@@ -48,8 +48,7 @@ struct BuildLog {
   /// happen when/if it's needed
   bool OpenForWrite(const std::string& path, const BuildLogUser& user,
                     std::string* err);
-  bool RecordCommand(Edge* edge, int start_time, int end_time,
-                     TimeStamp mtime = 0);
+  bool RecordCommand(Edge* edge, int start_time, int end_time);
   void Close();
 
   /// Load the on-disk log.
@@ -73,7 +72,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.

src/build_log_perftest.cc

@@ -93,8 +93,7 @@ bool WriteTestData(string* err) {
   for (int i = 0; i < kNumCommands; ++i) {
     log.RecordCommand(state.edges_[i],
                       /*start_time=*/100 * i,
-                      /*end_time=*/100 * i + 1,
-                      /*mtime=*/0);
+                      /*end_time=*/100 * i + 1);
   }
 
   return true;