[osr] Extend OSR tracing

New trace events:

- finished OSR compilation.
- entry into OSR code.

Since the latter now happens without a trip into runtime, tracing is a
bit more involved - we need to check FLAG_trace_osr in generated code,
and call a runtime function if it is set.

Drive-by: Slightly reorganize other OSR tracing.

Bug: v8:12161
Change-Id: I3096424ca7d47a19802281a0e0a39f7f3394c12b
Reviewed-on: https://chromium-review.googlesource.com/c/v8/v8/+/3629331
Commit-Queue: Camillo Bruni <cbruni@chromium.org>
Auto-Submit: Jakob Linke <jgruber@chromium.org>
Commit-Queue: Jakob Linke <jgruber@chromium.org>
Reviewed-by: Camillo Bruni <cbruni@chromium.org>
Cr-Commit-Position: refs/heads/main@{#80420}

src/builtins/arm/builtins-arm.cc

@@ -1863,6 +1863,24 @@ void OnStackReplacement(MacroAssembler* masm, OsrSourceTier source,
   __ bind(&jump_to_optimized_code);
   DCHECK_EQ(maybe_target_code, r0);  // Already in the right spot.
 
+  // OSR entry tracing.
+  {
+    Label next;
+    __ Move(r1, ExternalReference::address_of_FLAG_trace_osr());
+    __ ldr(r1, MemOperand(r1));
+    __ tst(r1, Operand(0xFF));  // Mask to the LSB.
+    __ b(eq, &next);
+
+    {
+      FrameAndConstantPoolScope scope(masm, StackFrame::INTERNAL);
+      __ Push(r0);  // Preserve the code object.
+      __ CallRuntime(Runtime::kTraceOptimizedOSREntry, 0);
+      __ Pop(r0);
+    }
+
+    __ bind(&next);
+  }
+
   if (source == OsrSourceTier::kInterpreter) {
     // Drop the handler frame that is be sitting on top of the actual
     // JavaScript frame. This is the case then OSR is triggered from bytecode.

src/builtins/arm64/builtins-arm64.cc

@@ -2095,6 +2095,25 @@ void OnStackReplacement(MacroAssembler* masm, OsrSourceTier source,
   __ Ret();
 
   __ Bind(&jump_to_optimized_code);
+  DCHECK_EQ(maybe_target_code, x0);  // Already in the right spot.
+
+  // OSR entry tracing.
+  {
+    Label next;
+    __ Mov(x1, ExternalReference::address_of_FLAG_trace_osr());
+    __ Ldr(x1, MemOperand(x1));
+    __ Tst(x1, 0xFF);  // Mask to the LSB.
+    __ B(eq, &next);
+
+    {
+      FrameScope scope(masm, StackFrame::INTERNAL);
+      __ Push(x0, padreg);  // Preserve the code object.
+      __ CallRuntime(Runtime::kTraceOptimizedOSREntry, 0);
+      __ Pop(padreg, x0);
+    }
+
+    __ Bind(&next);
+  }
 
   if (source == OsrSourceTier::kInterpreter) {
     // Drop the handler frame that is be sitting on top of the actual

src/builtins/ia32/builtins-ia32.cc

@@ -2844,6 +2844,25 @@ void OnStackReplacement(MacroAssembler* masm, OsrSourceTier source,
   __ ret(0);
 
   __ bind(&jump_to_optimized_code);
+  DCHECK_EQ(maybe_target_code, eax);  // Already in the right spot.
+
+  // OSR entry tracing.
+  {
+    Label next;
+    __ cmpb(__ ExternalReferenceAsOperand(
+                ExternalReference::address_of_FLAG_trace_osr(), ecx),
+            Immediate(0));
+    __ j(equal, &next, Label::kNear);
+
+    {
+      FrameScope scope(masm, StackFrame::INTERNAL);
+      __ Push(eax);  // Preserve the code object.
+      __ CallRuntime(Runtime::kTraceOptimizedOSREntry, 0);
+      __ Pop(eax);
+    }
+
+    __ bind(&next);
+  }
 
   if (source == OsrSourceTier::kInterpreter) {
     // Drop the handler frame that is be sitting on top of the actual

src/builtins/x64/builtins-x64.cc

@@ -2748,6 +2748,25 @@ void OnStackReplacement(MacroAssembler* masm, OsrSourceTier source,
   __ bind(&jump_to_optimized_code);
   DCHECK_EQ(maybe_target_code, rax);  // Already in the right spot.
 
+  // OSR entry tracing.
+  {
+    Label next;
+    __ cmpb(
+        __ ExternalReferenceAsOperand(
+            ExternalReference::address_of_FLAG_trace_osr(), kScratchRegister),
+        Immediate(0));
+    __ j(equal, &next, Label::kNear);
+
+    {
+      FrameScope scope(masm, StackFrame::INTERNAL);
+      __ Push(rax);  // Preserve the code object.
+      __ CallRuntime(Runtime::kTraceOptimizedOSREntry, 0);
+      __ Pop(rax);
+    }
+
+    __ bind(&next);
+  }
+
   if (source == OsrSourceTier::kInterpreter) {
     // Drop the handler frame that is be sitting on top of the actual
     // JavaScript frame. This is the case then OSR is triggered from bytecode.

src/codegen/compiler.cc

@@ -120,13 +120,37 @@ class CompilerTracer : public AllStatic {
     PrintTraceSuffix(scope);
   }
 
-  static void TraceOptimizeOSR(Isolate* isolate, Handle<JSFunction> function,
-                               BytecodeOffset osr_offset,
-                               ConcurrencyMode mode) {
+  static void TraceOptimizeOSRStarted(Isolate* isolate,
+                                      Handle<JSFunction> function,
+                                      BytecodeOffset osr_offset,
+                                      ConcurrencyMode mode) {
+    if (!FLAG_trace_osr) return;
+    CodeTracer::Scope scope(isolate->GetCodeTracer());
+    PrintF(
+        scope.file(),
+        "[OSR - compilation started. function: %s, osr offset: %d, mode: %s]\n",
+        function->DebugNameCStr().get(), osr_offset.ToInt(), ToString(mode));
+  }
+
+  static void TraceOptimizeOSRFinished(Isolate* isolate,
+                                       Handle<JSFunction> function,
+                                       BytecodeOffset osr_offset) {
+    if (!FLAG_trace_osr) return;
+    CodeTracer::Scope scope(isolate->GetCodeTracer());
+    PrintF(scope.file(),
+           "[OSR - compilation finished. function: %s, osr offset: %d]\n",
+           function->DebugNameCStr().get(), osr_offset.ToInt());
+  }
+
+  static void TraceOptimizeOSRAvailable(Isolate* isolate,
+                                        Handle<JSFunction> function,
+                                        BytecodeOffset osr_offset,
+                                        ConcurrencyMode mode) {
     if (!FLAG_trace_osr) return;
     CodeTracer::Scope scope(isolate->GetCodeTracer());
     PrintF(scope.file(),
-           "[OSR - started. function: %s, osr offset: %d, mode: %s]\n",
+           "[OSR - available (compilation completed or cache hit). function: "
+           "%s, osr offset: %d, mode: %s]\n",
            function->DebugNameCStr().get(), osr_offset.ToInt(), ToString(mode));
   }
 
@@ -3365,13 +3389,16 @@ MaybeHandle<CodeT> Compiler::CompileOptimizedOSR(Isolate* isolate,
 
   function->feedback_vector().reset_osr_urgency();
 
-  CompilerTracer::TraceOptimizeOSR(isolate, function, osr_offset, mode);
+  CompilerTracer::TraceOptimizeOSRStarted(isolate, function, osr_offset, mode);
   MaybeHandle<CodeT> result = GetOrCompileOptimized(
       isolate, function, mode, CodeKind::TURBOFAN, osr_offset, frame);
 
   if (result.is_null()) {
     CompilerTracer::TraceOptimizeOSRUnavailable(isolate, function, osr_offset,
                                                 mode);
+  } else {
+    CompilerTracer::TraceOptimizeOSRAvailable(isolate, function, osr_offset,
+                                              mode);
   }
 
   return result;
@@ -3429,7 +3456,10 @@ bool Compiler::FinalizeTurbofanCompilationJob(TurbofanCompilationJob* job,
             compilation_info->osr_offset(), ToCodeT(*compilation_info->code()),
             compilation_info->function_context_specializing());
         CompilerTracer::TraceCompletedJob(isolate, compilation_info);
-        if (!IsOSR(osr_offset)) {
+        if (IsOSR(osr_offset)) {
+          CompilerTracer::TraceOptimizeOSRFinished(isolate, function,
+                                                   osr_offset);
+        } else {
           function->set_code(*compilation_info->code(), kReleaseStore);
         }
       }

src/codegen/external-reference.cc

@@ -550,6 +550,12 @@ ExternalReference::address_of_mock_arraybuffer_allocator_flag() {
   return ExternalReference(&FLAG_mock_arraybuffer_allocator);
 }
 
+// TODO(jgruber): Update the other extrefs pointing at FLAG_ addresses to be
+// called address_of_FLAG_foo (easier grep-ability).
+ExternalReference ExternalReference::address_of_FLAG_trace_osr() {
+  return ExternalReference(&FLAG_trace_osr);
+}
+
 ExternalReference ExternalReference::address_of_builtin_subclassing_flag() {
   return ExternalReference(&FLAG_builtin_subclassing);
 }

src/codegen/external-reference.h

@@ -92,6 +92,7 @@ class StatsCounter;
 
 #define EXTERNAL_REFERENCE_LIST(V)                                             \
   V(abort_with_reason, "abort_with_reason")                                    \
+  V(address_of_FLAG_trace_osr, "FLAG_trace_osr")                               \
   V(address_of_builtin_subclassing_flag, "FLAG_builtin_subclassing")           \
   V(address_of_double_abs_constant, "double_absolute_constant")                \
   V(address_of_double_neg_constant, "double_negate_constant")                  \

src/runtime/runtime-compiler.cc

@@ -337,18 +337,12 @@ RUNTIME_FUNCTION(Runtime_CompileOptimizedOSR) {
   DCHECK(result->is_turbofanned());  // TODO(v8:7700): Support Maglev.
   DCHECK(CodeKindIsOptimizedJSFunction(result->kind()));
 
+#ifdef DEBUG
   DeoptimizationData data =
       DeoptimizationData::cast(result->deoptimization_data());
   DCHECK_EQ(BytecodeOffset(data.OsrBytecodeOffset().value()), osr_offset);
   DCHECK_GE(data.OsrPcOffset().value(), 0);
-
-  if (FLAG_trace_osr) {
-    CodeTracer::Scope scope(isolate->GetCodeTracer());
-    PrintF(scope.file(),
-           "[OSR - entry. function: %s, osr offset: %d, pc offset: %d]\n",
-           function->DebugNameCStr().get(), osr_offset.ToInt(),
-           data.OsrPcOffset().value());
-  }
+#endif  // DEBUG
 
   if (function->feedback_vector().invocation_count() <= 1 &&
       !IsNone(function->tiering_state()) &&
@@ -368,6 +362,27 @@ RUNTIME_FUNCTION(Runtime_CompileOptimizedOSR) {
   return *result;
 }
 
+RUNTIME_FUNCTION(Runtime_TraceOptimizedOSREntry) {
+  HandleScope handle_scope(isolate);
+  DCHECK_EQ(0, args.length());
+  CHECK(FLAG_trace_osr);
+
+  // Determine the frame that triggered the OSR request.
+  JavaScriptFrameIterator it(isolate);
+  UnoptimizedFrame* frame = UnoptimizedFrame::cast(it.frame());
+
+  // Determine the entry point for which this OSR request has been fired.
+  BytecodeOffset osr_offset = BytecodeOffset(frame->GetBytecodeOffset());
+  DCHECK(!osr_offset.IsNone());
+
+  Handle<JSFunction> function(frame->function(), isolate);
+  PrintF(CodeTracer::Scope{isolate->GetCodeTracer()}.file(),
+         "[OSR - entry. function: %s, osr offset: %d]\n",
+         function->DebugNameCStr().get(), osr_offset.ToInt());
+
+  return ReadOnlyRoots(isolate).undefined_value();
+}
+
 static Object CompileGlobalEval(Isolate* isolate,
                                 Handle<i::Object> source_object,
                                 Handle<SharedFunctionInfo> outer_info,

src/runtime/runtime.h

@@ -108,6 +108,7 @@ namespace internal {
 
 #define FOR_EACH_INTRINSIC_COMPILER(F, I) \
   F(CompileOptimizedOSR, 0, 1)            \
+  F(TraceOptimizedOSREntry, 0, 1)         \
   F(CompileLazy, 1, 1)                    \
   F(CompileBaseline, 1, 1)                \
   F(CompileMaglev_Concurrent, 1, 1)       \