[log] Support first function execution logging with --log-function-events

Bug: chromium:757467
Change-Id: I52f8100e0c8b4ac07e1f875e44cb468fa8ce572b
Reviewed-on: https://chromium-review.googlesource.com/793611Reviewed-by: Ross McIlroy <rmcilroy@chromium.org>
Reviewed-by: Leszek Swirski <leszeks@chromium.org>
Reviewed-by: Michael Lippautz <mlippautz@chromium.org>
Commit-Queue: Camillo Bruni <cbruni@chromium.org>
Cr-Commit-Position: refs/heads/master@{#49764}

src/builtins/arm/builtins-arm.cc

@@ -776,6 +776,9 @@ static void MaybeTailCallOptimizedCodeSlot(MacroAssembler* masm,
            Operand(Smi::FromEnum(OptimizationMarker::kNone)));
     __ b(eq, &fallthrough);
 
+    TailCallRuntimeIfMarkerEquals(masm, optimized_code_entry,
+                                  OptimizationMarker::kLogFirstExecution,
+                                  Runtime::kFunctionFirstExecution);
     TailCallRuntimeIfMarkerEquals(masm, optimized_code_entry,
                                   OptimizationMarker::kCompileOptimized,
                                   Runtime::kCompileOptimized_NotConcurrent);

src/builtins/arm64/builtins-arm64.cc

@@ -872,6 +872,9 @@ static void MaybeTailCallOptimizedCodeSlot(MacroAssembler* masm,
                         Operand(Smi::FromEnum(OptimizationMarker::kNone)), eq,
                         &fallthrough);
 
+    TailCallRuntimeIfMarkerEquals(masm, optimized_code_entry,
+                                  OptimizationMarker::kLogFirstExecution,
+                                  Runtime::kFunctionFirstExecution);
     TailCallRuntimeIfMarkerEquals(masm, optimized_code_entry,
                                   OptimizationMarker::kCompileOptimized,
                                   Runtime::kCompileOptimized_NotConcurrent);

src/builtins/ia32/builtins-ia32.cc

@@ -693,6 +693,9 @@ static void MaybeTailCallOptimizedCodeSlot(MacroAssembler* masm,
            Immediate(Smi::FromEnum(OptimizationMarker::kNone)));
     __ j(equal, &fallthrough);
 
+    TailCallRuntimeIfMarkerEquals(masm, optimized_code_entry,
+                                  OptimizationMarker::kLogFirstExecution,
+                                  Runtime::kFunctionFirstExecution);
     TailCallRuntimeIfMarkerEquals(masm, optimized_code_entry,
                                   OptimizationMarker::kCompileOptimized,
                                   Runtime::kCompileOptimized_NotConcurrent);

src/builtins/mips/builtins-mips.cc

@@ -751,6 +751,9 @@ static void MaybeTailCallOptimizedCodeSlot(MacroAssembler* masm,
     __ Branch(&fallthrough, eq, optimized_code_entry,
               Operand(Smi::FromEnum(OptimizationMarker::kNone)));
 
+    TailCallRuntimeIfMarkerEquals(masm, optimized_code_entry,
+                                  OptimizationMarker::kLogFirstExecution,
+                                  Runtime::kFunctionFirstExecution);
     TailCallRuntimeIfMarkerEquals(masm, optimized_code_entry,
                                   OptimizationMarker::kCompileOptimized,
                                   Runtime::kCompileOptimized_NotConcurrent);

src/builtins/mips64/builtins-mips64.cc

@@ -751,6 +751,9 @@ static void MaybeTailCallOptimizedCodeSlot(MacroAssembler* masm,
     __ Branch(&fallthrough, eq, optimized_code_entry,
               Operand(Smi::FromEnum(OptimizationMarker::kNone)));
 
+    TailCallRuntimeIfMarkerEquals(masm, optimized_code_entry,
+                                  OptimizationMarker::kLogFirstExecution,
+                                  Runtime::kFunctionFirstExecution);
     TailCallRuntimeIfMarkerEquals(masm, optimized_code_entry,
                                   OptimizationMarker::kCompileOptimized,
                                   Runtime::kCompileOptimized_NotConcurrent);

src/builtins/ppc/builtins-ppc.cc

@@ -772,6 +772,9 @@ static void MaybeTailCallOptimizedCodeSlot(MacroAssembler* masm,
                      Smi::FromEnum(OptimizationMarker::kNone), r0);
     __ beq(&fallthrough);
 
+    TailCallRuntimeIfMarkerEquals(masm, optimized_code_entry,
+                                  OptimizationMarker::kLogFirstExecution,
+                                  Runtime::kFunctionFirstExecution);
     TailCallRuntimeIfMarkerEquals(masm, optimized_code_entry,
                                   OptimizationMarker::kCompileOptimized,
                                   Runtime::kCompileOptimized_NotConcurrent);

src/builtins/s390/builtins-s390.cc

@@ -775,6 +775,9 @@ static void MaybeTailCallOptimizedCodeSlot(MacroAssembler* masm,
                      Smi::FromEnum(OptimizationMarker::kNone), r0);
     __ beq(&fallthrough);
 
+    TailCallRuntimeIfMarkerEquals(masm, optimized_code_entry,
+                                  OptimizationMarker::kLogFirstExecution,
+                                  Runtime::kFunctionFirstExecution);
     TailCallRuntimeIfMarkerEquals(masm, optimized_code_entry,
                                   OptimizationMarker::kCompileOptimized,
                                   Runtime::kCompileOptimized_NotConcurrent);

src/builtins/x64/builtins-x64.cc

@@ -767,6 +767,9 @@ static void MaybeTailCallOptimizedCodeSlot(MacroAssembler* masm,
                   Smi::FromEnum(OptimizationMarker::kNone));
     __ j(equal, &fallthrough);
 
+    TailCallRuntimeIfMarkerEquals(masm, optimized_code_entry,
+                                  OptimizationMarker::kLogFirstExecution,
+                                  Runtime::kFunctionFirstExecution);
     TailCallRuntimeIfMarkerEquals(masm, optimized_code_entry,
                                   OptimizationMarker::kCompileOptimized,
                                   Runtime::kCompileOptimized_NotConcurrent);

src/compiler.cc

@@ -513,7 +513,7 @@ void ClearOptimizedCodeCache(CompilationInfo* compilation_info) {
   if (compilation_info->osr_offset().IsNone()) {
     Handle<FeedbackVector> vector =
         handle(function->feedback_vector(), function->GetIsolate());
-    vector->ClearOptimizedCode();
+    vector->ClearOptimizationMarker();
   }
 }
 

src/feedback-vector-inl.h

@@ -117,7 +117,8 @@ bool FeedbackVector::has_optimized_code() const {
 }
 
 bool FeedbackVector::has_optimization_marker() const {
-  return optimization_marker() != OptimizationMarker::kNone;
+  return optimization_marker() != OptimizationMarker::kLogFirstExecution &&
+         optimization_marker() != OptimizationMarker::kNone;
 }
 
 // Conversion from an integer index to either a slot or an ic slot.

src/feedback-vector.cc

@@ -234,7 +234,9 @@ Handle<FeedbackVector> FeedbackVector::New(Isolate* isolate,
 
   DCHECK_EQ(vector->shared_function_info(), *shared);
   DCHECK_EQ(vector->optimized_code_cell(),
-            Smi::FromEnum(OptimizationMarker::kNone));
+            Smi::FromEnum(FLAG_log_function_events
+                              ? OptimizationMarker::kLogFirstExecution
+                              : OptimizationMarker::kNone));
   DCHECK_EQ(vector->invocation_count(), 0);
   DCHECK_EQ(vector->profiler_ticks(), 0);
   DCHECK_EQ(vector->deopt_count(), 0);
@@ -341,12 +343,18 @@ void FeedbackVector::SetOptimizedCode(Handle<FeedbackVector> vector,
   vector->set_optimized_code_cell(*cell);
 }
 
-void FeedbackVector::SetOptimizationMarker(OptimizationMarker marker) {
-  set_optimized_code_cell(Smi::FromEnum(marker));
+void FeedbackVector::ClearOptimizedCode() {
+  DCHECK(has_optimized_code());
+  SetOptimizationMarker(OptimizationMarker::kNone);
 }
 
-void FeedbackVector::ClearOptimizedCode() {
-  set_optimized_code_cell(Smi::FromEnum(OptimizationMarker::kNone));
+void FeedbackVector::ClearOptimizationMarker() {
+  DCHECK(!has_optimized_code());
+  SetOptimizationMarker(OptimizationMarker::kNone);
+}
+
+void FeedbackVector::SetOptimizationMarker(OptimizationMarker marker) {
+  set_optimized_code_cell(Smi::FromEnum(marker));
 }
 
 void FeedbackVector::EvictOptimizedCodeMarkedForDeoptimization(
@@ -356,7 +364,7 @@ void FeedbackVector::EvictOptimizedCodeMarkedForDeoptimization(
 
   WeakCell* cell = WeakCell::cast(slot);
   if (cell->cleared()) {
-    ClearOptimizedCode();
+    ClearOptimizationMarker();
     return;
   }
 

src/feedback-vector.h

@@ -174,6 +174,9 @@ class FeedbackVector : public HeapObject {
                                Handle<Code> code);
   void SetOptimizationMarker(OptimizationMarker marker);
 
+  // Clears the optimization marker in the feedback vector.
+  void ClearOptimizationMarker();
+
   // Conversion from a slot to an integer index to the underlying array.
   static int GetIndex(FeedbackSlot slot) { return slot.ToInt(); }
 

src/globals.h

@@ -1419,6 +1419,7 @@ inline std::ostream& operator<<(std::ostream& os,
 }
 
 enum class OptimizationMarker {
+  kLogFirstExecution,
   kNone,
   kCompileOptimized,
   kCompileOptimizedConcurrent,
@@ -1428,6 +1429,8 @@ enum class OptimizationMarker {
 inline std::ostream& operator<<(std::ostream& os,
                                 const OptimizationMarker& marker) {
   switch (marker) {
+    case OptimizationMarker::kLogFirstExecution:
+      return os << "OptimizationMarker::kLogFirstExecution";
     case OptimizationMarker::kNone:
       return os << "OptimizationMarker::kNone";
     case OptimizationMarker::kCompileOptimized:

src/heap/heap.cc

@@ -3977,7 +3977,9 @@ AllocationResult Heap::AllocateFeedbackVector(SharedFunctionInfo* shared,
   result->set_map_after_allocation(feedback_vector_map(), SKIP_WRITE_BARRIER);
   FeedbackVector* vector = FeedbackVector::cast(result);
   vector->set_shared_function_info(shared);
-  vector->set_optimized_code_cell(Smi::FromEnum(OptimizationMarker::kNone));
+  vector->set_optimized_code_cell(Smi::FromEnum(
+      FLAG_log_function_events ? OptimizationMarker::kLogFirstExecution
+                               : OptimizationMarker::kNone));
   vector->set_length(length);
   vector->set_invocation_count(0);
   vector->set_profiler_ticks(0);

src/objects-inl.h

@@ -4057,8 +4057,7 @@ bool JSFunction::HasOptimizationMarker() {
 
 void JSFunction::ClearOptimizationMarker() {
   DCHECK(has_feedback_vector());
-  DCHECK(!feedback_vector()->has_optimized_code());
-  feedback_vector()->SetOptimizationMarker(OptimizationMarker::kNone);
+  feedback_vector()->ClearOptimizationMarker();
 }
 
 bool JSFunction::IsInterpreted() {

src/objects-printer.cc

@@ -749,7 +749,12 @@ void FeedbackVector::FeedbackVectorPrint(std::ostream& os) {  // NOLINT
   }
 
   os << "\n SharedFunctionInfo: " << Brief(shared_function_info());
-  os << "\n Optimized Code: " << Brief(optimized_code_cell());
+  os << "\n Optimized Code/Marker: ";
+  if (has_optimized_code()) {
+    os << Brief(optimized_code());
+  } else {
+    os << optimization_marker();
+  }
   os << "\n Invocation Count: " << invocation_count();
   os << "\n Profiler Ticks: " << profiler_ticks();
 

src/runtime/runtime-compiler.cc

@@ -57,6 +57,24 @@ RUNTIME_FUNCTION(Runtime_CompileOptimized_Concurrent) {
   return function->code();
 }
 
+RUNTIME_FUNCTION(Runtime_FunctionFirstExecution) {
+  HandleScope scope(isolate);
+  StackLimitCheck check(isolate);
+  DCHECK_EQ(1, args.length());
+
+  CONVERT_ARG_HANDLE_CHECKED(JSFunction, function, 0);
+  DCHECK_EQ(function->feedback_vector()->optimization_marker(),
+            OptimizationMarker::kLogFirstExecution);
+  DCHECK(FLAG_log_function_events);
+  Handle<SharedFunctionInfo> sfi(function->shared());
+  LOG(isolate, FunctionEvent("first-execution", Script::cast(sfi->script()), -1,
+                             0, sfi->start_position(), sfi->end_position(),
+                             sfi->DebugName()));
+  function->feedback_vector()->ClearOptimizationMarker();
+  // Return the code to continue execution, we don't care at this point whether
+  // this is for lazy compilation or has been eagerly complied.
+  return function->code();
+}
 
 RUNTIME_FUNCTION(Runtime_CompileOptimized_NotConcurrent) {
   HandleScope scope(isolate);

src/runtime/runtime.h

@@ -120,6 +120,7 @@ namespace internal {
 #define FOR_EACH_INTRINSIC_COMPILER(F)    \
   F(CompileLazy, 1, 1)                    \
   F(CompileOptimized_Concurrent, 1, 1)    \
+  F(FunctionFirstExecution, 1, 1)         \
   F(CompileOptimized_NotConcurrent, 1, 1) \
   F(EvictOptimizedCodeSlot, 1, 1)         \
   F(NotifyDeoptimized, 0, 1)              \

test/cctest/test-log.cc

@@ -885,6 +885,9 @@ TEST(ConsoleTimeEvents) {
 }
 
 TEST(LogFunctionEvents) {
+  // Always opt and stress opt will break the fine-grained log order.
+  if (i::FLAG_always_opt) return;
+
   SETUP_FLAGS();
   i::FLAG_log_function_events = true;
   v8::Isolate::CreateParams create_params;
@@ -936,14 +939,21 @@ TEST(LogFunctionEvents) {
         //         - execute eager functions.
         {"function,parse-function,", ",lazyFunction"},
         {"function,compile-lazy,", ",lazyFunction"},
+        {"function,first-execution,", ",lazyFunction"},
 
         {"function,parse-function,", ",lazyInnerFunction"},
         {"function,compile-lazy,", ",lazyInnerFunction"},
+        {"function,first-execution,", ",lazyInnerFunction"},
+
+        {"function,first-execution,", ",eagerFunction"},
 
         {"function,parse-function,", ",Foo"},
         {"function,compile-lazy,", ",Foo"},
+        {"function,first-execution,", ",Foo"},
+
         {"function,parse-function,", ",Foo.foo"},
         {"function,compile-lazy,", ",Foo.foo"},
+        {"function,first-execution,", ",Foo.foo"},
     };
     logger.FindLogLines(pairs, arraysize(pairs), start);
   }