"explain" debug prints just before each command is run

The explanations are printed just before each command is run. Before, it
would potentially print pages & pages of explanations at the beginning,
and it was hard to tell which explanation caused a particular command to
run.

Edges that are pruned due to "restat" used to print all their
explanations at the beginning, cluttering up the output with
explanations that didn't actually cause any rebuilding. Now, those
explanations aren't printed if those edges aren't run.

src/build.cc

@@ -1057,8 +1057,6 @@ bool Builder::ExtractDeps(CommandRunner::Result* result,
 }
 
 bool Builder::LoadDyndeps(Node* node, string* err) {
-  status_->BuildLoadDyndeps();
-
   // Load the dyndep information provided by this node.
   DyndepFile ddf;
   if (!scan_.LoadDyndeps(node, &ddf, err))

src/debug_flags.cc

@@ -12,6 +12,13 @@
 // See the License for the specific language governing permissions and
 // limitations under the License.
 
+#include <stdio.h>
+#include <map>
+#include <vector>
+#include <string>
+
+#include "graph.h"
+
 bool g_explaining = false;
 
 bool g_keep_depfile = false;
@@ -19,3 +26,21 @@ bool g_keep_depfile = false;
 bool g_keep_rsp = false;
 
 bool g_experimental_statcache = true;
+
+// Reasons each Node needs rebuilding, for "-d explain".
+typedef std::map<const Node*, std::vector<std::string> > Explanations;
+static Explanations explanations_;
+
+void record_explanation(const Node* node, std::string explanation) {
+  explanations_[node].push_back(explanation);
+}
+
+void print_explanations(FILE *stream, const Edge* edge) {
+  for (std::vector<Node*>::const_iterator o = edge->outputs_.begin();
+       o != edge->outputs_.end(); ++o) {
+    for (std::vector<std::string>::iterator s = explanations_[*o].begin();
+         s != explanations_[*o].end(); ++s) {
+      fprintf(stream, "ninja explain: %s\n", (*s).c_str());
+    }
+  }
+}

src/debug_flags.h

@@ -17,12 +17,20 @@
 
 #include <stdio.h>
 
-#define EXPLAIN(fmt, ...) {                                             \
-  if (g_explaining)                                                     \
-    fprintf(stderr, "ninja explain: " fmt "\n", __VA_ARGS__);           \
+#define EXPLAIN(node, fmt, ...) {                                       \
+  if (g_explaining) {                                                   \
+    char buf[1024];                                                     \
+    snprintf(buf, 1024, fmt, __VA_ARGS__);                              \
+    record_explanation(node, buf);                                      \
+  }                                                                     \
 }
 
+struct Edge;
+struct Node;
+
 extern bool g_explaining;
+void record_explanation(const Node* node, std::string reason);
+void print_explanations(FILE *stream, const Edge* node);
 
 extern bool g_keep_depfile;
 

src/dyndep.cc

@@ -37,7 +37,7 @@ bool DyndepLoader::LoadDyndeps(Node* node, DyndepFile* ddf,
   node->set_dyndep_pending(false);
 
   // Load the dyndep information from the file.
-  EXPLAIN("loading dyndep file '%s'", node->path().c_str());
+  EXPLAIN(node, "loading dyndep file '%s'", node->path().c_str());
   if (!LoadDyndepFile(node, ddf, err))
     return false;
 

src/graph.cc

@@ -91,7 +91,7 @@ bool DependencyScan::RecomputeNodeDirty(Node* node, std::vector<Node*>* stack,
     if (!node->StatIfNecessary(disk_interface_, err))
       return false;
     if (!node->exists())
-      EXPLAIN("%s has no in-edge and is missing", node->path().c_str());
+      EXPLAIN(node, "%s has no in-edge and is missing", node->path().c_str());
     node->set_dirty(!node->exists());
     return true;
   }
@@ -182,7 +182,7 @@ bool DependencyScan::RecomputeNodeDirty(Node* node, std::vector<Node*>* stack,
       // If a regular input is dirty (or missing), we're dirty.
       // Otherwise consider mtime.
       if ((*i)->dirty()) {
-        EXPLAIN("%s is dirty", (*i)->path().c_str());
+        EXPLAIN(node, "%s is dirty", (*i)->path().c_str());
         dirty = true;
       } else {
         if (!most_recent_input || (*i)->mtime() > most_recent_input->mtime()) {
@@ -282,7 +282,7 @@ bool DependencyScan::RecomputeOutputDirty(const Edge* edge,
     // Phony edges don't write any output.  Outputs are only dirty if
     // there are no inputs and we're missing the output.
     if (edge->inputs_.empty() && !output->exists()) {
-      EXPLAIN("output %s of phony edge with no inputs doesn't exist",
+      EXPLAIN(output, "output %s of phony edge with no inputs doesn't exist",
               output->path().c_str());
       return true;
     }
@@ -299,7 +299,7 @@ bool DependencyScan::RecomputeOutputDirty(const Edge* edge,
 
   // Dirty if we're missing the output.
   if (!output->exists()) {
-    EXPLAIN("output %s doesn't exist", output->path().c_str());
+    EXPLAIN(output, "output %s doesn't exist", output->path().c_str());
     return true;
   }
 
@@ -319,7 +319,7 @@ bool DependencyScan::RecomputeOutputDirty(const Edge* edge,
 
   // Dirty if the output is older than the input.
   if (!used_restat && most_recent_input && output->mtime() < most_recent_input->mtime()) {
-    EXPLAIN("output %s older than most recent input %s "
+    EXPLAIN(output, "output %s older than most recent input %s "
             "(%" PRId64 " vs %" PRId64 ")",
             output->path().c_str(),
             most_recent_input->path().c_str(),
@@ -335,7 +335,7 @@ bool DependencyScan::RecomputeOutputDirty(const Edge* edge,
         // May also be dirty due to the command changing since the last build.
         // But if this is a generator rule, the command changing does not make us
         // dirty.
-        EXPLAIN("command line changed for %s", output->path().c_str());
+        EXPLAIN(output, "command line changed for %s", output->path().c_str());
         return true;
       }
       if (most_recent_input && entry->mtime < most_recent_input->mtime()) {
@@ -345,14 +345,16 @@ bool DependencyScan::RecomputeOutputDirty(const Edge* edge,
         // exited with an error or was interrupted. If this was a restat rule,
         // then we only check the recorded mtime against the most recent input
         // mtime and ignore the actual output's mtime above.
-        EXPLAIN("recorded mtime of %s older than most recent input %s (%" PRId64 " vs %" PRId64 ")",
+        EXPLAIN(output,
+                "recorded mtime of %s older than most recent input %s (%" PRId64 " vs %" PRId64 ")",
                 output->path().c_str(), most_recent_input->path().c_str(),
                 entry->mtime, most_recent_input->mtime());
         return true;
       }
     }
     if (!entry && !generator) {
-      EXPLAIN("command line not found in log for %s", output->path().c_str());
+      EXPLAIN(output, "command line not found in log for %s",
+              output->path().c_str());
       return true;
     }
   }
@@ -666,8 +668,9 @@ bool ImplicitDepLoader::LoadDepFile(Edge* edge, const string& path,
     return false;
   }
   // On a missing depfile: return false and empty *err.
+  Node* first_output = edge->outputs_[0];
   if (content.empty()) {
-    EXPLAIN("depfile '%s' is missing", path.c_str());
+    EXPLAIN(first_output, "depfile '%s' is missing", path.c_str());
     return false;
   }
 
@@ -692,11 +695,11 @@ bool ImplicitDepLoader::LoadDepFile(Edge* edge, const string& path,
 
   // Check that this depfile matches the edge's output, if not return false to
   // mark the edge as dirty.
-  Node* first_output = edge->outputs_[0];
   StringPiece opath = StringPiece(first_output->path());
   if (opath != *primary_out) {
-    EXPLAIN("expected depfile '%s' to mention '%s', got '%s'", path.c_str(),
-            first_output->path().c_str(), primary_out->AsString().c_str());
+    EXPLAIN(first_output, "expected depfile '%s' to mention '%s', got '%s'",
+            path.c_str(), first_output->path().c_str(),
+            primary_out->AsString().c_str());
     return false;
   }
 
@@ -737,13 +740,14 @@ bool ImplicitDepLoader::LoadDepsFromLog(Edge* edge, string* err) {
   Node* output = edge->outputs_[0];
   DepsLog::Deps* deps = deps_log_ ? deps_log_->GetDeps(output) : NULL;
   if (!deps) {
-    EXPLAIN("deps for '%s' are missing", output->path().c_str());
+    EXPLAIN(output, "deps for '%s' are missing", output->path().c_str());
     return false;
   }
 
   // Deps are invalid if the output is newer than the deps.
   if (output->mtime() > deps->mtime) {
-    EXPLAIN("stored deps info out of date for '%s' (%" PRId64 " vs %" PRId64 ")",
+    EXPLAIN(output,
+            "stored deps info out of date for '%s' (%" PRId64 " vs %" PRId64 ")",
             output->path().c_str(), deps->mtime, output->mtime());
     return false;
   }

src/status.h

@@ -30,7 +30,6 @@ struct Status {
   virtual void BuildEdgeFinished(Edge* edge, int64_t start_time_millis,
                                  int64_t end_time_millis, bool success,
                                  const std::string& output) = 0;
-  virtual void BuildLoadDyndeps() = 0;
   virtual void BuildStarted() = 0;
   virtual void BuildFinished() = 0;
 

src/status_printer.cc

@@ -247,20 +247,6 @@ void StatusPrinter::BuildEdgeFinished(Edge* edge, int64_t start_time_millis,
   }
 }
 
-void StatusPrinter::BuildLoadDyndeps() {
-  // The DependencyScan calls EXPLAIN() to print lines explaining why
-  // it considers a portion of the graph to be out of date.  Normally
-  // this is done before the build starts, but our caller is about to
-  // load a dyndep file during the build.  Doing so may generate more
-  // explanation lines (via fprintf directly to stderr), but in an
-  // interactive console the cursor is currently at the end of a status
-  // line.  Start a new line so that the first explanation does not
-  // append to the status line.  After the explanations are done a
-  // new build status line will appear.
-  if (g_explaining)
-    printer_.PrintOnNewLine("");
-}
-
 void StatusPrinter::BuildStarted() {
   started_edges_ = 0;
   finished_edges_ = 0;
@@ -417,6 +403,13 @@ string StatusPrinter::FormatProgressStatus(const char* progress_status_format,
 }
 
 void StatusPrinter::PrintStatus(const Edge* edge, int64_t time_millis) {
+  if (g_explaining) {
+    // Start a new line so that the first explanation does not append to the
+    // status line.
+    printer_.PrintOnNewLine("");
+    print_explanations(stderr, edge);
+  }
+
   if (config_.verbosity == BuildConfig::QUIET
       || config_.verbosity == BuildConfig::NO_STATUS_UPDATE)
     return;

src/status_printer.h

@@ -32,7 +32,6 @@ struct StatusPrinter : Status {
   virtual void BuildEdgeFinished(Edge* edge, int64_t start_time_millis,
                                  int64_t end_time_millis, bool success,
                                  const std::string& output);
-  virtual void BuildLoadDyndeps();
   virtual void BuildStarted();
   virtual void BuildFinished();