From 95d13c2ee3116b9e4f16465298ec563331c5c80f Mon Sep 17 00:00:00 2001
From: Clemens Hammacher <clemensh@chromium.org>
Date: Tue, 28 Nov 2017 13:44:14 +0100
Subject: [PATCH] [wasm] Add tracing for lazy compilation

This CL adds the --trace-wasm-lazy-compilation flag, to track which
function is being compiled, and how many locations in the caller and in
function tables are actually being patched.
It seems that we currently don't patch the caller correctly when
calling through wasm-to-wasm stubs, and this tracing helps to find the
issue.

Drive-by: Fix order and location of macro undefs.

R=titzer@chromium.org

Bug: chromium:788441
Change-Id: I6091c0d490a729f8e3cb759cd661cf52129d2211
Reviewed-on: https://chromium-review.googlesource.com/793157
Reviewed-by: Ben Titzer <titzer@chromium.org>
Commit-Queue: Clemens Hammacher <clemensh@chromium.org>
Cr-Commit-Position: refs/heads/master@{#49669}
---
 src/flag-definitions.h      |  2 ++
 src/wasm/module-compiler.cc | 27 +++++++++++++++++++++++++--
 2 files changed, 27 insertions(+), 2 deletions(-)

diff --git a/src/flag-definitions.h b/src/flag-definitions.h
index 9b9565db2a7..18c53180af9 100644
--- a/src/flag-definitions.h
+++ b/src/flag-definitions.h
@@ -556,6 +556,8 @@ DEFINE_BOOL(asm_wasm_lazy_compilation, false,
 DEFINE_IMPLICATION(validate_asm, asm_wasm_lazy_compilation)
 DEFINE_BOOL(wasm_lazy_compilation, false,
             "enable lazy compilation for all wasm modules")
+DEFINE_BOOL(trace_wasm_lazy_compilation, false,
+            "trace lazy compilation of wasm functions")
 // wasm-interpret-all resets {asm-,}wasm-lazy-compilation.
 DEFINE_NEG_IMPLICATION(wasm_interpret_all, asm_wasm_lazy_compilation)
 DEFINE_NEG_IMPLICATION(wasm_interpret_all, wasm_lazy_compilation)
diff --git a/src/wasm/module-compiler.cc b/src/wasm/module-compiler.cc
index 48aeae3252b..2d521a0936b 100644
--- a/src/wasm/module-compiler.cc
+++ b/src/wasm/module-compiler.cc
@@ -44,6 +44,12 @@
   do {                                                  \
     if (FLAG_trace_wasm_streaming) PrintF(__VA_ARGS__); \
   } while (false)
+
+#define TRACE_LAZY(...)                                        \
+  do {                                                         \
+    if (FLAG_trace_wasm_lazy_compilation) PrintF(__VA_ARGS__); \
+  } while (false)
+
 static const int kInvalidSigIndex = -1;
 
 namespace v8 {
@@ -341,6 +347,8 @@ class InstanceBuilder {
   ERROR_THROWER_WITH_MESSAGE(LinkError)
   ERROR_THROWER_WITH_MESSAGE(TypeError)
 
+#undef ERROR_THROWER_WITH_MESSAGE
+
   // Look up an import value in the {ffi_} object.
   MaybeHandle<Object> LookupImport(uint32_t index, Handle<String> module_name,
                                    Handle<String> import_name);
@@ -658,6 +666,8 @@ Handle<Code> CompileLazy(Isolate* isolate) {
   Handle<Code> compiled_code = WasmCompiledModule::CompileLazy(
       isolate, instance, caller_code, offset, func_index, patch_caller);
   if (!exp_deopt_data.is_null() && exp_deopt_data->length() > 2) {
+    TRACE_LAZY("Patching %d position(s) in function tables.\n",
+               (exp_deopt_data->length() - 2) / 2);
     // See EnsureExportedLazyDeoptData: exp_deopt_data[2...(len-1)] are pairs of
     // <export_table, index> followed by undefined values.
     // Use this information here to patch all export tables.
@@ -807,6 +817,11 @@ Handle<Code> LazyCompilationOrchestrator::CompileLazy(
   Handle<WasmCompiledModule> compiled_module(instance->compiled_module(),
                                              isolate);
 
+  TRACE_LAZY(
+      "Starting lazy compilation (func %d @%d, js-to-wasm: %d, "
+      "patch caller: %d).\n",
+      exported_func_index, call_offset, is_js_to_wasm, patch_caller);
+
   if (is_js_to_wasm) {
     non_compiled_functions.push_back({0, exported_func_index});
   } else if (patch_caller) {
@@ -846,6 +861,8 @@ Handle<Code> LazyCompilationOrchestrator::CompileLazy(
     }
   }
 
+  TRACE_LAZY("Compiling function %d.\n", func_to_return_idx);
+
   // TODO(clemensh): compile all functions in non_compiled_functions in
   // background, wait for func_to_return_idx.
   CompileFunction(isolate, instance, func_to_return_idx);
@@ -856,6 +873,7 @@ Handle<Code> LazyCompilationOrchestrator::CompileLazy(
     CodeSpaceMemoryModificationScope modification_scope(isolate->heap());
     // Now patch the code object with all functions which are now compiled.
     int idx = 0;
+    int patched = 0;
     for (RelocIterator it(*caller, RelocInfo::kCodeTargetMask); !it.done();
          it.next()) {
       Code* callee =
@@ -883,8 +901,13 @@ Handle<Code> LazyCompilationOrchestrator::CompileLazy(
       DCHECK_EQ(Code::WASM_FUNCTION, callee_compiled->kind());
       it.rinfo()->set_target_address(isolate,
                                      callee_compiled->instruction_start());
+      ++patched;
     }
     DCHECK_EQ(non_compiled_functions.size(), idx);
+    TRACE_LAZY("Patched %d location(s) in the caller.\n", patched);
+    // TODO(clemensh, crbug.com/788441): Fix patching issues, enable this check.
+    // DCHECK_LT(0, patched);
+    USE(patched);
   }
 
   Code* ret =
@@ -3540,7 +3563,7 @@ void CompileJsToWasmWrappers(Isolate* isolate,
 }  // namespace v8
 
 #undef TRACE
+#undef TRACE_CHAIN
 #undef TRACE_COMPILE
 #undef TRACE_STREAMING
-#undef TRACE_CHAIN
-#undef ERROR_THROWER_WITH_MESSAGE
+#undef TRACE_LAZY
-- 
2.18.1