Merge pull request #2067 from drothlis/explain-laterupstream-master

Print "explain" debug just before each command is run

9 files changed, 131 insertions, 54 deletions

diff --git a/misc/output_test.py b/misc/output_test.py
index c72faf5..cba3ff0 100755
--- a/misc/output_test.py
+++ b/misc/output_test.py
@@ -11,6 +11,7 @@ import subprocess
 import sys
 import tempfile
 import unittest
+from textwrap import dedent
 from typing import Dict
 
 default_env = dict(os.environ)
@@ -19,35 +20,56 @@ default_env.pop('CLICOLOR_FORCE', None)
 default_env['TERM'] = ''
 NINJA_PATH = os.path.abspath('./ninja')
 
-def run(
-    build_ninja: str,
-    flags: str = '',
-    pipe: bool = False,
-    env: Dict[str, str] = default_env,
-) -> str:
-    with tempfile.TemporaryDirectory() as d:
-        with open(os.path.join(d, 'build.ninja'), 'w') as f:
-            f.write(build_ninja)
+class BuildDir:
+    def __init__(self, build_ninja: str):
+        self.build_ninja = dedent(build_ninja)
+        self.d = None
+
+    def __enter__(self):
+        self.d = tempfile.TemporaryDirectory()
+        with open(os.path.join(self.d.name, 'build.ninja'), 'w') as f:
+            f.write(self.build_ninja)
             f.flush()
+        return self
+
+    def __exit__(self, exc_type, exc_val, exc_tb):
+        self.d.cleanup()
+
+    def run(
+        self,
+        flags: str = '',
+        pipe: bool = False,
+        env: Dict[str, str] = default_env,
+    ) -> str:
         ninja_cmd = '{} {}'.format(NINJA_PATH, flags)
         try:
             if pipe:
-                output = subprocess.check_output([ninja_cmd], shell=True, cwd=d, env=env)
+                output = subprocess.check_output(
+                    [ninja_cmd], shell=True, cwd=self.d.name, env=env)
             elif platform.system() == 'Darwin':
                 output = subprocess.check_output(['script', '-q', '/dev/null', 'bash', '-c', ninja_cmd],
-                                                 cwd=d, env=env)
+                                                 cwd=self.d.name, env=env)
             else:
                 output = subprocess.check_output(['script', '-qfec', ninja_cmd, '/dev/null'],
-                                                 cwd=d, env=env)
+                                                 cwd=self.d.name, env=env)
         except subprocess.CalledProcessError as err:
             sys.stdout.buffer.write(err.output)
             raise err
-    final_output = ''
-    for line in output.decode('utf-8').splitlines(True):
-        if len(line) > 0 and line[-1] == '\r':
-            continue
-        final_output += line.replace('\r', '')
-    return final_output
+        final_output = ''
+        for line in output.decode('utf-8').splitlines(True):
+            if len(line) > 0 and line[-1] == '\r':
+                continue
+            final_output += line.replace('\r', '')
+        return final_output
+
+def run(
+    build_ninja: str,
+    flags: str = '',
+    pipe: bool = False,
+    env: Dict[str, str] = default_env,
+) -> str:
+    with BuildDir(build_ninja) as b:
+        return b.run(flags, pipe, env)
 
 @unittest.skipIf(platform.system() == 'Windows', 'These test methods do not work on Windows')
 class Output(unittest.TestCase):
@@ -191,6 +213,35 @@ out1
 out2
 ''')
 
+    def test_explain_output(self):
+        b = BuildDir('''\
+            build .FORCE: phony
+            rule create_if_non_exist
+              command = [ -e $out ] || touch $out
+              restat = true
+            rule write
+              command = cp $in $out
+            build input : create_if_non_exist .FORCE
+            build mid : write input
+            build output : write mid
+            default output
+            ''')
+        with b:
+            # The explain output is shown just before the relevant build:
+            self.assertEqual(b.run('-v -d explain'), dedent('''\
+                ninja explain: .FORCE is dirty
+                [1/3] [ -e input ] || touch input
+                ninja explain: input is dirty
+                [2/3] cp input mid
+                ninja explain: mid is dirty
+                [3/3] cp mid output
+                '''))
+            # Don't print "ninja explain: XXX is dirty" for inputs that are
+            # pruned from the graph by an earlier restat.
+            self.assertEqual(b.run('-v -d explain'), dedent('''\
+                ninja explain: .FORCE is dirty
+                [1/3] [ -e input ] || touch input
+                '''))
 
 if __name__ == '__main__':
     unittest.main()
diff --git a/src/build.cc b/src/build.cc
index e52345b..e05a3d2 100644
--- a/src/build.cc
+++ b/src/build.cc
@@ -1095,8 +1095,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))
diff --git a/src/debug_flags.cc b/src/debug_flags.cc
index 44b14c4..e90d8f3 100644
--- a/src/debug_flags.cc
+++ b/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());
+    }
+  }
+}
diff --git a/src/debug_flags.h b/src/debug_flags.h
index e08a43b..d2480bb 100644
--- a/src/debug_flags.h
+++ b/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;
 
diff --git a/src/dyndep.cc b/src/dyndep.cc
index 112d1cb..1eadbcb 100644
--- a/src/dyndep.cc
+++ b/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;
 
diff --git a/src/graph.cc b/src/graph.cc
index 31b109a..0156a89 100644
--- a/src/graph.cc
+++ b/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;
   }
diff --git a/src/status.h b/src/status.h
index 8071b9e..e38b4e6 100644
--- a/src/status.h
+++ b/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;
 
diff --git a/src/status_printer.cc b/src/status_printer.cc
index 6bd7333..577aa93 100644
--- a/src/status_printer.cc
+++ b/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;
diff --git a/src/status_printer.h b/src/status_printer.h
index 5b1486f..1681fb8 100644
--- a/src/status_printer.h
+++ b/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();