Log nested pass names in BINARYEN_PASS_DEBUG=2 (#3214)

We can't validate or print out the wasm in that case, but at least
logging the names as they run can help debug some situations.

2 files changed, 20 insertions, 12 deletions

diff --git a/src/pass.h b/src/pass.h
index 27e7ee37f..4f9cd1b68 100644
--- a/src/pass.h
+++ b/src/pass.h
@@ -226,9 +226,11 @@ struct PassRunner {
   //                     doesn't help anyhow and also is bad for e.g. printing
   //                     which is a pass)
   // this method returns whether we are in passDebug mode, and which value:
-  //  1: run pass by pass, validating in between
-  //  2: also save the last pass, so it breakage happens we can print the last
-  //  one 3: also dump out byn-* files for each pass
+  //  1: log out each pass that we run, and validate in between (can pass
+  //     --no-validation to skip validation).
+  //  2: like 1, and also save the last pass's output, so if breakage happens we
+  //     can print a useful error. also logs out names of nested passes.
+  //  3: like 1, and also dumps out byn-* files for each pass as it is run.
   static int getPassDebug();
 
 protected:
diff --git a/src/passes/pass.cpp b/src/passes/pass.cpp
index d115b4533..9b56fa54d 100644
--- a/src/passes/pass.cpp
+++ b/src/passes/pass.cpp
@@ -546,27 +546,33 @@ static void dumpWast(Name name, Module* wasm) {
 
 void PassRunner::run() {
   static const int passDebug = getPassDebug();
-  if (!isNested && (options.debug || passDebug)) {
+  // Emit logging information when asked for. At passDebug level 1+ we log
+  // the main passes, while in 2 we also log nested ones. Note that for
+  // nested ones we can only emit their name - we can't validate, or save the
+  // file, or print, as the wasm may be in an intermediate state that is not
+  // valid.
+  if (options.debug || (passDebug == 2 || (passDebug && !isNested))) {
     // for debug logging purposes, run each pass in full before running the
     // other
     auto totalTime = std::chrono::duration<double>(0);
-    size_t padding = 0;
     WasmValidator::Flags validationFlags = WasmValidator::Minimal;
     if (options.validateGlobally) {
       validationFlags = validationFlags | WasmValidator::Globally;
     }
-    std::cerr << "[PassRunner] running passes..." << std::endl;
+    auto what = isNested ? "nested passes" : "passes";
+    std::cerr << "[PassRunner] running " << what << std::endl;
+    size_t padding = 0;
     for (auto& pass : passes) {
       padding = std::max(padding, pass->name.size());
     }
-    if (passDebug >= 3) {
+    if (passDebug >= 3 && !isNested) {
       dumpWast("before", wasm);
     }
     for (auto& pass : passes) {
       // ignoring the time, save a printout of the module before, in case this
       // pass breaks it, so we can print the before and after
       std::stringstream moduleBefore;
-      if (passDebug == 2) {
+      if (passDebug == 2 && !isNested) {
         WasmPrinter::printModule(wasm, moduleBefore);
       }
       // prepare to run
@@ -586,7 +592,7 @@ void PassRunner::run() {
       std::chrono::duration<double> diff = after - before;
       std::cerr << diff.count() << " seconds." << std::endl;
       totalTime += diff;
-      if (options.validate) {
+      if (options.validate && !isNested) {
         // validate, ignoring the time
         std::cerr << "[PassRunner]   (validating)\n";
         if (!WasmValidator().validate(*wasm, validationFlags)) {
@@ -607,9 +613,9 @@ void PassRunner::run() {
         dumpWast(pass->name, wasm);
       }
     }
-    std::cerr << "[PassRunner] passes took " << totalTime.count() << " seconds."
-              << std::endl;
-    if (options.validate) {
+    std::cerr << "[PassRunner] " << what << " took " << totalTime.count()
+              << " seconds." << std::endl;
+    if (options.validate && !isNested) {
       std::cerr << "[PassRunner] (final validation)\n";
       if (!WasmValidator().validate(*wasm, validationFlags)) {
         WasmPrinter::printModule(wasm);