[wasm] New flags for tracing compilation times

--trace-wasm-compilation-times: print one line per compiled function
      with basic performance information. Useful for narrowing down
      functions of interest before investigating them in more depth.
--wasm-tier-up-filter=N: only tier up function #N. Useful for focusing
      features like --turbo-stats-wasm on a particular function.

Change-Id: Iaddb29bf815f4de8381a08e29187e96cc9945779
Reviewed-on: https://chromium-review.googlesource.com/c/v8/v8/+/3086341Reviewed-by: Manos Koukoutos <manoskouk@chromium.org>
Reviewed-by: Nico Hartmann <nicohartmann@chromium.org>
Commit-Queue: Jakob Kummerow <jkummerow@chromium.org>
Cr-Commit-Position: refs/heads/main@{#77399}

src/compiler/pipeline.cc

@@ -3208,6 +3208,10 @@ void Pipeline::GenerateCodeForWasmFunction(
     const wasm::WasmModule* module, int function_index,
     std::vector<compiler::WasmLoopInfo>* loop_info) {
   auto* wasm_engine = wasm::GetWasmEngine();
+  base::TimeTicks start_time;
+  if (V8_UNLIKELY(FLAG_trace_wasm_compilation_times)) {
+    start_time = base::TimeTicks::Now();
+  }
   ZoneStats zone_stats(wasm_engine->allocator());
   std::unique_ptr<PipelineStatistics> pipeline_statistics(
       CreatePipelineStatistics(function_body, module, info, &zone_stats));
@@ -3305,6 +3309,19 @@ void Pipeline::GenerateCodeForWasmFunction(
         << " using TurboFan" << std::endl;
   }
 
+  if (V8_UNLIKELY(FLAG_trace_wasm_compilation_times)) {
+    base::TimeDelta time = base::TimeTicks::Now() - start_time;
+    int codesize = result->code_desc.body_size();
+    StdoutStream{} << "Compiled function "
+                   << reinterpret_cast<const void*>(module) << "#"
+                   << function_index << " using TurboFan, took "
+                   << time.InMilliseconds() << " ms and "
+                   << zone_stats.GetMaxAllocatedBytes() << " / "
+                   << zone_stats.GetTotalAllocatedBytes()
+                   << " max/total bytes, codesize " << codesize << " name "
+                   << data.info()->GetDebugName().get() << std::endl;
+  }
+
   DCHECK(result->succeeded());
   info->SetWasmCompilationResult(std::move(result));
 }

src/compiler/wasm-compiler.cc

@@ -7970,6 +7970,11 @@ wasm::WasmCompilationResult ExecuteTurbofanWasmCompilation(
           zone_bytes);
     }
   }
+  // If we tiered up only one function for debugging, dump statistics
+  // immediately.
+  if (V8_UNLIKELY(FLAG_turbo_stats_wasm && FLAG_wasm_tier_up_filter >= 0)) {
+    wasm::GetWasmEngine()->DumpTurboStatistics();
+  }
   auto result = info.ReleaseWasmCompilationResult();
   CHECK_NOT_NULL(result);  // Compilation expected to succeed.
   DCHECK_EQ(wasm::ExecutionTier::kTurbofan, result->result_tier);

src/flags/flag-definitions.h

@@ -961,6 +961,9 @@ DEFINE_BOOL(wasm_dynamic_tiering, false,
 DEFINE_INT(
     wasm_caching_threshold, 1000000,
     "the amount of wasm top tier code that triggers the next caching event")
+DEFINE_BOOL(trace_wasm_compilation_times, false,
+            "print how long it took to compile each wasm function")
+DEFINE_INT(wasm_tier_up_filter, -1, "only tier-up function with this index")
 DEFINE_DEBUG_BOOL(trace_wasm_decoder, false, "trace decoding of wasm code")
 DEFINE_DEBUG_BOOL(trace_wasm_compiler, false, "trace compiling of wasm code")
 DEFINE_DEBUG_BOOL(trace_wasm_interpreter, false,

src/wasm/baseline/liftoff-compiler.cc

@@ -6346,6 +6346,10 @@ constexpr base::EnumSet<ValueKind> LiftoffCompiler::kUnconditionallySupported;
 WasmCompilationResult ExecuteLiftoffCompilation(
     CompilationEnv* env, const FunctionBody& func_body, int func_index,
     ForDebugging for_debugging, const LiftoffOptions& compiler_options) {
+  base::TimeTicks start_time;
+  if (V8_UNLIKELY(FLAG_trace_wasm_compilation_times)) {
+    start_time = base::TimeTicks::Now();
+  }
   int func_body_size = static_cast<int>(func_body.end - func_body.start);
   TRACE_EVENT2(TRACE_DISABLED_BY_DEFAULT("v8.wasm.detailed"),
                "wasm.CompileBaseline", "funcIndex", func_index, "bodySize",
@@ -6408,6 +6412,17 @@ WasmCompilationResult ExecuteLiftoffCompilation(
   }
   result.feedback_vector_slots = compiler->GetFeedbackVectorSlots();
 
+  if (V8_UNLIKELY(FLAG_trace_wasm_compilation_times)) {
+    base::TimeDelta time = base::TimeTicks::Now() - start_time;
+    int codesize = result.code_desc.body_size();
+    StdoutStream{} << "Compiled function "
+                   << reinterpret_cast<const void*>(env->module) << "#"
+                   << func_index << " using Liftoff, took "
+                   << time.InMilliseconds() << " ms and "
+                   << zone.allocation_size() << " bytes; bodysize "
+                   << func_body_size << " codesize " << codesize << std::endl;
+  }
+
   DCHECK(result.succeeded());
   return result;
 }

src/wasm/module-compiler.cc

@@ -952,7 +952,10 @@ ExecutionTierPair GetRequestedExecutionTiers(
       Impl(native_module->compilation_state())->dynamic_tiering() ==
       DynamicTiering::kEnabled;
   bool tier_up_enabled = !dynamic_tiering && FLAG_wasm_tier_up;
-  if (module->origin != kWasmOrigin || !tier_up_enabled) {
+  if (module->origin != kWasmOrigin || !tier_up_enabled ||
+      V8_UNLIKELY(FLAG_wasm_tier_up_filter >= 0 &&
+                  func_index !=
+                      static_cast<uint32_t>(FLAG_wasm_tier_up_filter))) {
     result.top_tier = result.baseline_tier;
     return result;
   }

src/wasm/wasm-engine.cc

@@ -893,6 +893,14 @@ void WasmEngine::DumpAndResetTurboStatistics() {
   compilation_stats_.reset();
 }
 
+void WasmEngine::DumpTurboStatistics() {
+  base::MutexGuard guard(&mutex_);
+  if (compilation_stats_ != nullptr) {
+    StdoutStream os;
+    os << AsPrintableStatistics{*compilation_stats_.get(), false} << std::endl;
+  }
+}
+
 CodeTracer* WasmEngine::GetCodeTracer() {
   base::MutexGuard guard(&mutex_);
   if (code_tracer_ == nullptr) code_tracer_.reset(new CodeTracer(-1));

src/wasm/wasm-engine.h

@@ -226,6 +226,8 @@ class V8_EXPORT_PRIVATE WasmEngine {
 
   // Prints the gathered compilation statistics, then resets them.
   void DumpAndResetTurboStatistics();
+  // Same, but no reset.
+  void DumpTurboStatistics();
 
   // Used to redirect tracing output from {stdout} to a file.
   CodeTracer* GetCodeTracer();

tools/process-wasm-compilation-times.py

+#!/usr/bin/env python3
+# Copyright 2021 the V8 project authors. All rights reserved.
+# Use of this source code is governed by a BSD-style license that can be
+# found in the LICENSE file.
+
+# Processes {stdout} output generated by --trace-wasm-compilation-times
+# for easier consumption by human readers.
+
+import sys
+
+def SizeInternal(number, suffix):
+  if suffix == "": return "%d" % number
+  if number < 10: return "%.1f%s" % (number, suffix)
+  return "%d%s" % (number, suffix)
+
+def Size(number):
+  if (number < 1024): return SizeInternal(number, "")
+  number /= 1024
+  if (number < 1024): return SizeInternal(number, "K")
+  number /= 1024
+  if (number < 1024): return SizeInternal(number, "M")
+  number /= 1024
+  if (number < 1024): return SizeInternal(number, "G")
+  return SizeInternal(number / 1024, "T")
+
+modules = {}
+max_module = 0
+total_tf_time = 0
+total_tf_size = 0
+
+def RegisterName(raw):
+  global max_module
+  parts = raw.split("#")
+  m = parts[0]
+  if m not in modules:
+    modules[m] = max_module
+    max_module += 1
+
+def Name(raw):
+  parts = raw.split("#")
+  if len(modules) == 1: return "#%s" % parts[1]
+  return "m%d#%s" % (modules[parts[0]], parts[1])
+
+class Function:
+  def __init__(self, index):
+    self.index = index
+    self.has_lo = False
+    self.has_tf = False
+    self.time_lo = -1
+    self.time_tf = -1
+    self.mem_lo = -1
+    self.mem_tf_max = -1
+    self.mem_tf_total = -1
+    self.name = ""
+    self.size_wasm = -1
+    self.size_lo = -1
+    self.size_tf = -1
+
+  def AddLine(self, words):
+    assert self.index == words[2], "wrong function"
+    if words[4] == "TurboFan,":
+      self.AddTFLine(words)
+    elif words[4] == "Liftoff,":
+      self.AddLiftoffLine(words)
+    else:
+      raise Exception("unknown compiler: %s" % words[4])
+
+  def AddTFLine(self, words):
+    assert not self.has_tf, "duplicate TF line for %s" % self.index
+    self.has_tf = True
+    # 0        1        2  3     4         5    6 7  8   9     10 11
+    # Compiled function #6 using TurboFan, took 0 ms and 14440 / 44656
+    # 12        13     14       15 16   17
+    # max/total bytes, codesize 24 name wasm-function#6
+    self.time_tf = int(words[6])
+    self.mem_tf_max = int(words[9])
+    self.mem_tf_total = int(words[11])
+    self.size_tf = int(words[15])
+    self.name = words[17]
+
+  def AddLiftoffLine(self, words):
+    assert self.index == words[2], "wrong function"
+    assert not self.has_lo, "duplicate Liftoff line for %s" % self.index
+    self.has_lo = True
+    # 0        1        2  3     4        5    6 7  8   9   10     11       12
+    # Compiled function #6 using Liftoff, took 0 ms and 968 bytes; bodysize 4
+    # 13       14
+    # codesize 68
+    self.time_lo = int(words[6])
+    self.mem_lo = int(words[9])
+    self.size_lo = int(words[14])
+    self.size_wasm = int(words[12])
+
+  def __str__(self):
+    return "%s: time %d %d mem %s %s %s size %s %s %s name %s" % (
+      Name(self.index), self.time_lo, self.time_tf,
+      Size(self.mem_lo), Size(self.mem_tf_max), Size(self.mem_tf_total),
+      Size(self.size_wasm), Size(self.size_lo), Size(self.size_tf), self.name
+    )
+
+funcs_dict = {}
+funcs_list = []
+
+if len(sys.argv) < 2 or sys.argv[1] in ("-h", "--help", "help"):
+  print("Pass output file (generated with --trace-wasm-compilation-times) as "
+        "argument")
+  sys.exit(1)
+
+with open(sys.argv[1], "r") as f:
+  for line in f.readlines():
+    words = line.strip().split(" ")
+    if words[0] != "Compiled": continue
+    name = words[2]
+    RegisterName(name)
+    if name in funcs_dict:
+      func = funcs_dict[name]
+    else:
+      func = Function(name)
+      funcs_dict[name] = func
+      funcs_list.append(func)
+    func.AddLine(words)
+
+funcs_list.sort(key=lambda fun: fun.time_tf)
+for f in funcs_list:
+  print(f)
+  total_tf_time += f.time_tf
+  total_tf_size += f.size_tf
+
+print("Total TF time: %d" % total_tf_time)
+print("Total TF size: %d" % total_tf_size)