Add some tracing to wasm-emscripten-finalize (#2505)

Also fix, but in splitting the names of the trace channels.  Obviously
I can't write string.split correctly in C first time around.

3 files changed, 30 insertions, 9 deletions

diff --git a/src/support/debug.cpp b/src/support/debug.cpp
index da006e9c0..ab5401bfc 100644
--- a/src/support/debug.cpp
+++ b/src/support/debug.cpp
@@ -45,7 +45,7 @@ void wasm::setDebugEnabled(const char* types) {
     if (type_end == nullptr) {
       type_end = types + end;
     }
-    size_t type_size = type_end - types + start;
+    size_t type_size = type_end - (types + start);
     std::string type(types + start, type_size);
     debugTypesEnabled.insert(type);
     start += type_size + 1;
diff --git a/src/tools/wasm-emscripten-finalize.cpp b/src/tools/wasm-emscripten-finalize.cpp
index c1d104c6a..f569b54cb 100644
--- a/src/tools/wasm-emscripten-finalize.cpp
+++ b/src/tools/wasm-emscripten-finalize.cpp
@@ -24,6 +24,7 @@
 #include "abi/js.h"
 #include "ir/trapping.h"
 #include "support/colors.h"
+#include "support/debug.h"
 #include "support/file.h"
 #include "tool-options.h"
 #include "wasm-binary.h"
@@ -32,6 +33,8 @@
 #include "wasm-printing.h"
 #include "wasm-validator.h"
 
+#define DEBUG_TYPE "emscripten"
+
 using namespace cashew;
 using namespace wasm;
 
@@ -175,10 +178,9 @@ int main(int argc, const char* argv[]) {
 
   options.applyFeatures(wasm);
 
-  if (options.debug) {
-    std::cerr << "Module before:\n";
-    WasmPrinter::printModule(&wasm, std::cerr);
-  }
+  BYN_TRACE_WITH_TYPE("emscripten-dump", "Module before:\n");
+  BYN_DEBUG_WITH_TYPE("emscripten-dump",
+                      WasmPrinter::printModule(&wasm, std::cerr));
 
   uint32_t dataSize = 0;
 
@@ -226,9 +228,11 @@ int main(int argc, const char* argv[]) {
   }
 
   if (isSideModule) {
+    BYN_TRACE("finalizing as side module\n");
     generator.replaceStackPointerGlobal();
     generator.generatePostInstantiateFunction();
   } else {
+    BYN_TRACE("finalizing as regular module\n");
     generator.generateRuntimeFunctions();
     generator.internalizeStackPointerGlobal();
     generator.generateMemoryGrowthFunction();
@@ -260,6 +264,7 @@ int main(int argc, const char* argv[]) {
 
   // Legalize the wasm.
   {
+    BYN_TRACE("legalizing types\n");
     PassRunner passRunner(&wasm);
     passRunner.setOptions(options.passOptions);
     passRunner.setDebug(options.debug);
@@ -270,6 +275,7 @@ int main(int argc, const char* argv[]) {
     passRunner.run();
   }
 
+  BYN_TRACE("generated metadata\n");
   // Substantial changes to the wasm are done, enough to create the metadata.
   std::string metadata =
     generator.generateEmscriptenMetadata(dataSize, initializerFunctions);
@@ -284,10 +290,9 @@ int main(int argc, const char* argv[]) {
     generator.separateDataSegments(&memInitFile, globalBase);
   }
 
-  if (options.debug) {
-    std::cerr << "Module after:\n";
-    WasmPrinter::printModule(&wasm, std::cerr);
-  }
+  BYN_TRACE_WITH_TYPE("emscripten-dump", "Module after:\n");
+  BYN_DEBUG_WITH_TYPE("emscripten-dump",
+                      WasmPrinter::printModule(&wasm, std::cerr));
 
   // Strip target features section (its information is in the metadata)
   {
diff --git a/src/wasm/wasm-emscripten.cpp b/src/wasm/wasm-emscripten.cpp
index dae125096..695561f68 100644
--- a/src/wasm/wasm-emscripten.cpp
+++ b/src/wasm/wasm-emscripten.cpp
@@ -25,10 +25,13 @@
 #include "ir/literal-utils.h"
 #include "ir/module-utils.h"
 #include "shared-constants.h"
+#include "support/debug.h"
 #include "wasm-builder.h"
 #include "wasm-traversal.h"
 #include "wasm.h"
 
+#define DEBUG_TYPE "emscripten"
+
 namespace wasm {
 
 cashew::IString EM_ASM_PREFIX("emscripten_asm_const");
@@ -122,6 +125,7 @@ inline Expression* stackBoundsCheck(Builder& builder,
 Expression*
 EmscriptenGlueGenerator::generateStoreStackPointer(Function* func,
                                                    Expression* value) {
+  BYN_TRACE("generateStoreStackPointer\n");
   if (!useStackPointerGlobal) {
     return builder.makeStore(
       /* bytes  =*/4,
@@ -147,6 +151,7 @@ EmscriptenGlueGenerator::generateStoreStackPointer(Function* func,
 }
 
 void EmscriptenGlueGenerator::generateStackSaveFunction() {
+  BYN_TRACE("generateStackSaveFunction\n");
   std::vector<NameType> params{};
   Function* function =
     builder.makeFunction(STACK_SAVE, std::move(params), i32, {});
@@ -157,6 +162,7 @@ void EmscriptenGlueGenerator::generateStackSaveFunction() {
 }
 
 void EmscriptenGlueGenerator::generateStackAllocFunction() {
+  BYN_TRACE("generateStackAllocFunction\n");
   std::vector<NameType> params{{"0", i32}};
   Function* function =
     builder.makeFunction(STACK_ALLOC, std::move(params), i32, {{"1", i32}});
@@ -181,6 +187,7 @@ void EmscriptenGlueGenerator::generateStackAllocFunction() {
 }
 
 void EmscriptenGlueGenerator::generateStackRestoreFunction() {
+  BYN_TRACE("generateStackRestoreFunction\n");
   std::vector<NameType> params{{"0", i32}};
   Function* function =
     builder.makeFunction(STACK_RESTORE, std::move(params), none, {});
@@ -193,6 +200,7 @@ void EmscriptenGlueGenerator::generateStackRestoreFunction() {
 }
 
 void EmscriptenGlueGenerator::generateRuntimeFunctions() {
+  BYN_TRACE("generateRuntimeFunctions\n");
   generateStackSaveFunction();
   generateStackAllocFunction();
   generateStackRestoreFunction();
@@ -229,6 +237,7 @@ ensureFunctionImport(Module* module, Name name, std::string sig) {
 // Here we internalize all such wasm globals and generte code that sets their
 // value based on the result of call `g$foo` and `fp$bar` functions at runtime.
 Function* EmscriptenGlueGenerator::generateAssignGOTEntriesFunction() {
+  BYN_TRACE("generateAssignGOTEntriesFunction\n");
   std::vector<Global*> gotFuncEntries;
   std::vector<Global*> gotMemEntries;
   for (auto& g : wasm.globals) {
@@ -307,6 +316,7 @@ Function* EmscriptenGlueGenerator::generateAssignGOTEntriesFunction() {
 // The later is the constructor function generaed by lld which performs any
 // fixups on the memory section and calls static constructors.
 void EmscriptenGlueGenerator::generatePostInstantiateFunction() {
+  BYN_TRACE("generatePostInstantiateFunction\n");
   Builder builder(wasm);
   Function* post_instantiate =
     builder.makeFunction(POST_INSTANTIATE, std::vector<NameType>{}, none, {});
@@ -1039,6 +1049,7 @@ struct FixInvokeFunctionNamesWalker
     }
 
     assert(importRenames.count(curr->name) == 0);
+    BYN_TRACE("renaming: " << curr->name << " -> " << newname << "\n");
     importRenames[curr->name] = newname;
     // Either rename or remove the existing import
     if (wasm.getFunctionOrNull(newname) || !newImports.insert(newname).second) {
@@ -1065,8 +1076,10 @@ struct FixInvokeFunctionNamesWalker
 };
 
 void EmscriptenGlueGenerator::fixInvokeFunctionNames() {
+  BYN_TRACE("fixInvokeFunctionNames\n");
   FixInvokeFunctionNamesWalker walker(wasm);
   walker.walkModule(&wasm);
+  BYN_TRACE("generating dyncall thunks\n");
   for (auto sig : walker.invokeSigs) {
     generateDynCallThunk(sig);
   }
@@ -1275,12 +1288,15 @@ void EmscriptenGlueGenerator::exportWasiStart() {
   // If main exists, export a function to call it per the wasi standard.
   Name main = "main";
   if (!wasm.getFunctionOrNull(main)) {
+    BYN_TRACE("exportWasiStart: main not found\n");
     return;
   }
   Name _start = "_start";
   if (wasm.getExportOrNull(_start)) {
+    BYN_TRACE("exportWasiStart: _start already present\n");
     return;
   }
+  BYN_TRACE("exportWasiStart\n");
   Builder builder(wasm);
   auto* body = builder.makeDrop(builder.makeCall(
     main,