[ic] Add feedback vector update tracing

Add the --trace-feedback-updates flag (disabled by default, enabled by
the v8_enable_trace_feedback_updates gn arg), which traces updates to
feedback slots.

Change-Id: Ib8f02f958e2adf04abda5d4ed680e29fa04895ab
Reviewed-on: https://chromium-review.googlesource.com/725814Reviewed-by: Toon Verwaest <verwaest@chromium.org>
Reviewed-by: Camillo Bruni <cbruni@chromium.org>
Commit-Queue: Leszek Swirski <leszeks@chromium.org>
Cr-Commit-Position: refs/heads/master@{#48983}

BUILD.gn

@@ -83,6 +83,9 @@ declare_args() {
   # Sets -dV8_TRACE_IGNITION.
   v8_enable_trace_ignition = false
 
+  # Sets -dV8_TRACE_FEEDBACK_UPDATES.
+  v8_enable_trace_feedback_updates = false
+
   # Sets -dV8_CONCURRENT_MARKING
   v8_enable_concurrent_marking = true
 
@@ -270,6 +273,9 @@ config("features") {
   if (v8_enable_trace_ignition) {
     defines += [ "V8_TRACE_IGNITION" ]
   }
+  if (v8_enable_trace_feedback_updates) {
+    defines += [ "V8_TRACE_FEEDBACK_UPDATES" ]
+  }
   if (v8_enable_v8_checks) {
     defines += [ "V8_ENABLE_CHECKS" ]
   }

src/code-stub-assembler.cc

@@ -7195,15 +7195,29 @@ void CodeStubAssembler::UpdateFeedback(Node* feedback, Node* feedback_vector,
   {
     StoreFeedbackVectorSlot(feedback_vector, slot_id, combined_feedback,
                             SKIP_WRITE_BARRIER);
-    // Reset profiler ticks.
-    StoreObjectFieldNoWriteBarrier(
-        feedback_vector, FeedbackVector::kProfilerTicksOffset, SmiConstant(0));
+    ReportFeedbackUpdate(feedback_vector, slot_id, "UpdateFeedback");
     Goto(&end);
   }
 
   BIND(&end);
 }
 
+void CodeStubAssembler::ReportFeedbackUpdate(
+    SloppyTNode<FeedbackVector> feedback_vector, SloppyTNode<IntPtrT> slot_id,
+    const char* reason) {
+  // Reset profiler ticks.
+  StoreObjectFieldNoWriteBarrier(
+      feedback_vector, FeedbackVector::kProfilerTicksOffset, Int32Constant(0),
+      MachineRepresentation::kWord32);
+
+#ifdef V8_TRACE_FEEDBACK_UPDATES
+  // Trace the update.
+  CallRuntime(Runtime::kInterpreterTraceUpdateFeedback, NoContextConstant(),
+              LoadFromParentFrame(JavaScriptFrameConstants::kFunctionOffset),
+              SmiTag(slot_id), StringConstant(reason));
+#endif  // V8_TRACE_FEEDBACK_UPDATES
+}
+
 void CodeStubAssembler::CombineFeedback(Variable* existing_feedback,
                                         Node* feedback) {
   existing_feedback->Bind(SmiOr(existing_feedback->value(), feedback));

src/code-stub-assembler.h

@@ -1589,6 +1589,11 @@ class V8_EXPORT_PRIVATE CodeStubAssembler : public compiler::CodeAssembler {
   // Update the type feedback vector.
   void UpdateFeedback(Node* feedback, Node* feedback_vector, Node* slot_id);
 
+  // Report that there was a feedback update, performing any tasks that should
+  // be done after a feedback update.
+  void ReportFeedbackUpdate(SloppyTNode<FeedbackVector> feedback_vector,
+                            SloppyTNode<IntPtrT> slot_id, const char* reason);
+
   // Combine the new feedback with the existing_feedback.
   void CombineFeedback(Variable* existing_feedback, Node* feedback);
 

src/feedback-vector.h

@@ -232,6 +232,8 @@ class FeedbackVector : public HeapObject {
   DECL_PRINTER(FeedbackVector)
   DECL_VERIFIER(FeedbackVector)
 
+  void FeedbackSlotPrint(std::ostream& os, FeedbackSlot slot);  // NOLINT
+
   // Clears the vector slots. Return true if feedback has changed.
   bool ClearSlots(Isolate* isolate);
 
@@ -282,6 +284,9 @@ class FeedbackVector : public HeapObject {
   static void AddToVectorsForProfilingTools(Isolate* isolate,
                                             Handle<FeedbackVector> vector);
 
+  void FeedbackSlotPrint(std::ostream& os, FeedbackSlot slot,
+                         FeedbackSlotKind kind);  // NOLINT
+
   DISALLOW_IMPLICIT_CONSTRUCTORS(FeedbackVector);
 };
 

src/flag-definitions.h

@@ -331,6 +331,11 @@ DEFINE_STRING(print_bytecode_filter, "*",
 DEFINE_BOOL(trace_ignition, false,
             "trace the bytecodes executed by the ignition interpreter")
 #endif
+#ifdef V8_TRACE_FEEDBACK_UPDATES
+DEFINE_BOOL(
+    trace_feedback_updates, false,
+    "trace updates to feedback vectors during ignition interpreter execution.")
+#endif
 DEFINE_BOOL(trace_ignition_codegen, false,
             "trace the codegen of ignition interpreter bytecode handlers")
 DEFINE_BOOL(trace_ignition_dispatches, false,

src/ic/ic.cc

@@ -307,18 +307,43 @@ MaybeHandle<Object> IC::ReferenceError(Handle<Name> name) {
 
 // static
 void IC::OnFeedbackChanged(Isolate* isolate, FeedbackVector* vector,
-                           JSFunction* host_function) {
+                           FeedbackSlot slot, JSFunction* host_function,
+                           const char* reason) {
   if (FLAG_trace_opt_verbose) {
     // TODO(leszeks): The host function is only needed for this print, we could
     // remove it as a parameter if we're of with removing this trace (or only
     // tracing the feedback vector, not the function name).
     if (vector->profiler_ticks() != 0) {
       PrintF("[resetting ticks for ");
-      host_function->PrintName();
-      PrintF(" due from %d due to IC change]\n", vector->profiler_ticks());
+      host_function->ShortPrint();
+      PrintF(" due from %d due to IC change: %s]\n", vector->profiler_ticks(),
+             reason);
     }
   }
   vector->set_profiler_ticks(0);
+
+#ifdef V8_TRACE_FEEDBACK_UPDATES
+  if (FLAG_trace_feedback_updates) {
+    int slot_count = vector->metadata()->slot_count();
+
+    OFStream os(stdout);
+    if (slot.IsInvalid()) {
+      os << "[Feedback slots in ";
+    } else {
+      os << "[Feedback slot " << slot.ToInt() << "/" << slot_count << " in ";
+    }
+    vector->shared_function_info()->ShortPrint(os);
+    if (slot.IsInvalid()) {
+      os << " updated - ";
+    } else {
+      os << " updated to ";
+      vector->FeedbackSlotPrint(os, slot);
+      os << " - ";
+    }
+    os << reason << "]" << std::endl;
+  }
+#endif
+
   isolate->runtime_profiler()->NotifyICChanged();
   // TODO(2029): When an optimized function is patched, it would
   // be nice to propagate the corresponding type information to its
@@ -344,7 +369,9 @@ void IC::ConfigureVectorState(IC::State new_state, Handle<Object> key) {
   }
 
   vector_set_ = true;
-  OnFeedbackChanged(isolate(), *vector(), GetHostFunction());
+  OnFeedbackChanged(
+      isolate(), *vector(), slot(), GetHostFunction(),
+      new_state == PREMONOMORPHIC ? "Premonomorphic" : "Megamorphic");
 }
 
 void IC::ConfigureVectorState(Handle<Name> name, Handle<Map> map,
@@ -359,7 +386,8 @@ void IC::ConfigureVectorState(Handle<Name> name, Handle<Map> map,
   }
 
   vector_set_ = true;
-  OnFeedbackChanged(isolate(), *vector(), GetHostFunction());
+  OnFeedbackChanged(isolate(), *vector(), slot(), GetHostFunction(),
+                    IsLoadGlobalIC() ? "LoadGlobal" : "Monomorphic");
 }
 
 void IC::ConfigureVectorState(Handle<Name> name, MapHandles const& maps,
@@ -370,7 +398,8 @@ void IC::ConfigureVectorState(Handle<Name> name, MapHandles const& maps,
   nexus()->ConfigurePolymorphic(name, maps, handlers);
 
   vector_set_ = true;
-  OnFeedbackChanged(isolate(), *vector(), GetHostFunction());
+  OnFeedbackChanged(isolate(), *vector(), slot(), GetHostFunction(),
+                    "Polymorphic");
 }
 
 MaybeHandle<Object> LoadIC::Load(Handle<Object> object, Handle<Name> name) {

src/ic/ic.h

@@ -64,7 +64,8 @@ class IC {
 
   // Nofity the IC system that a feedback has changed.
   static void OnFeedbackChanged(Isolate* isolate, FeedbackVector* vector,
-                                JSFunction* host_function);
+                                FeedbackSlot slot, JSFunction* host_function,
+                                const char* reason);
 
  protected:
   Address fp() const { return fp_; }

src/interpreter/interpreter-assembler.cc

@@ -669,10 +669,7 @@ void InterpreterAssembler::CollectCallableFeedback(Node* target, Node* context,
       }
       BIND(&done_loop);
       CreateWeakCellInFeedbackVector(feedback_vector, SmiTag(slot_id), target);
-      // Reset profiler ticks.
-      StoreObjectFieldNoWriteBarrier(feedback_vector,
-                                     FeedbackVector::kProfilerTicksOffset,
-                                     SmiConstant(0));
+      ReportFeedbackUpdate(feedback_vector, slot_id, "Call:Initialize");
       Goto(&done);
     }
 
@@ -686,10 +683,8 @@ void InterpreterAssembler::CollectCallableFeedback(Node* target, Node* context,
           feedback_vector, slot_id,
           HeapConstant(FeedbackVector::MegamorphicSentinel(isolate())),
           SKIP_WRITE_BARRIER);
-      // Reset profiler ticks.
-      StoreObjectFieldNoWriteBarrier(feedback_vector,
-                                     FeedbackVector::kProfilerTicksOffset,
-                                     SmiConstant(0));
+      ReportFeedbackUpdate(feedback_vector, slot_id,
+                           "Call:TransitionMegamorphic");
       Goto(&done);
     }
   }
@@ -873,10 +868,8 @@ Node* InterpreterAssembler::Construct(Node* target, Node* context,
       {
         var_site.Bind(CreateAllocationSiteInFeedbackVector(feedback_vector,
                                                            SmiTag(slot_id)));
-        // Reset profiler ticks.
-        StoreObjectFieldNoWriteBarrier(feedback_vector,
-                                       FeedbackVector::kProfilerTicksOffset,
-                                       SmiConstant(0));
+        ReportFeedbackUpdate(feedback_vector, slot_id,
+                             "Construct:CreateAllocationSite");
         Goto(&construct_array);
       }
 
@@ -884,10 +877,8 @@ Node* InterpreterAssembler::Construct(Node* target, Node* context,
       {
         CreateWeakCellInFeedbackVector(feedback_vector, SmiTag(slot_id),
                                        new_target);
-        // Reset profiler ticks.
-        StoreObjectFieldNoWriteBarrier(feedback_vector,
-                                       FeedbackVector::kProfilerTicksOffset,
-                                       SmiConstant(0));
+        ReportFeedbackUpdate(feedback_vector, slot_id,
+                             "Construct:CreateWeakCell");
         Goto(&construct);
       }
     }
@@ -902,10 +893,8 @@ Node* InterpreterAssembler::Construct(Node* target, Node* context,
           feedback_vector, slot_id,
           HeapConstant(FeedbackVector::MegamorphicSentinel(isolate())),
           SKIP_WRITE_BARRIER);
-      // Reset profiler ticks.
-      StoreObjectFieldNoWriteBarrier(feedback_vector,
-                                     FeedbackVector::kProfilerTicksOffset,
-                                     SmiConstant(0));
+      ReportFeedbackUpdate(feedback_vector, slot_id,
+                           "Construct:TransitionMegamorphic");
       Goto(&construct);
     }
   }
@@ -1007,10 +996,8 @@ Node* InterpreterAssembler::ConstructWithSpread(Node* target, Node* context,
 
       CreateWeakCellInFeedbackVector(feedback_vector, SmiTag(slot_id),
                                      new_target);
-      // Reset profiler ticks.
-      StoreObjectFieldNoWriteBarrier(feedback_vector,
-                                     FeedbackVector::kProfilerTicksOffset,
-                                     SmiConstant(0));
+      ReportFeedbackUpdate(feedback_vector, slot_id,
+                           "ConstructWithSpread:Initialize");
       Goto(&construct);
     }
 
@@ -1024,10 +1011,8 @@ Node* InterpreterAssembler::ConstructWithSpread(Node* target, Node* context,
           feedback_vector, slot_id,
           HeapConstant(FeedbackVector::MegamorphicSentinel(isolate())),
           SKIP_WRITE_BARRIER);
-      // Reset profiler ticks.
-      StoreObjectFieldNoWriteBarrier(feedback_vector,
-                                     FeedbackVector::kProfilerTicksOffset,
-                                     SmiConstant(0));
+      ReportFeedbackUpdate(feedback_vector, slot_id,
+                           "ConstructWithSpread:TransitionMegamorphic");
       Goto(&construct);
     }
   }

src/objects-printer.cc

@@ -745,81 +745,8 @@ void FeedbackVector::FeedbackVectorPrint(std::ostream& os) {  // NOLINT
     FeedbackSlot slot = iter.Next();
     FeedbackSlotKind kind = iter.kind();
 
-    os << "\n Slot " << slot << " " << kind;
-    os << " ";
-    switch (kind) {
-      case FeedbackSlotKind::kLoadProperty: {
-        LoadICNexus nexus(this, slot);
-        os << Code::ICState2String(nexus.StateFromFeedback());
-        break;
-      }
-      case FeedbackSlotKind::kLoadGlobalInsideTypeof:
-      case FeedbackSlotKind::kLoadGlobalNotInsideTypeof: {
-        LoadGlobalICNexus nexus(this, slot);
-        os << Code::ICState2String(nexus.StateFromFeedback());
-        break;
-      }
-      case FeedbackSlotKind::kLoadKeyed: {
-        KeyedLoadICNexus nexus(this, slot);
-        os << Code::ICState2String(nexus.StateFromFeedback());
-        break;
-      }
-      case FeedbackSlotKind::kCall: {
-        CallICNexus nexus(this, slot);
-        os << Code::ICState2String(nexus.StateFromFeedback());
-        break;
-      }
-      case FeedbackSlotKind::kStoreNamedSloppy:
-      case FeedbackSlotKind::kStoreNamedStrict:
-      case FeedbackSlotKind::kStoreOwnNamed:
-      case FeedbackSlotKind::kStoreGlobalSloppy:
-      case FeedbackSlotKind::kStoreGlobalStrict: {
-        StoreICNexus nexus(this, slot);
-        os << Code::ICState2String(nexus.StateFromFeedback());
-        break;
-      }
-      case FeedbackSlotKind::kStoreKeyedSloppy:
-      case FeedbackSlotKind::kStoreKeyedStrict: {
-        KeyedStoreICNexus nexus(this, slot);
-        os << Code::ICState2String(nexus.StateFromFeedback());
-        break;
-      }
-      case FeedbackSlotKind::kBinaryOp: {
-        BinaryOpICNexus nexus(this, slot);
-        os << Code::ICState2String(nexus.StateFromFeedback()) << " ("
-           << nexus.GetBinaryOperationFeedback() << ")";
-        break;
-      }
-      case FeedbackSlotKind::kCompareOp: {
-        CompareICNexus nexus(this, slot);
-        os << Code::ICState2String(nexus.StateFromFeedback()) << " ("
-           << nexus.GetCompareOperationFeedback() << ")";
-        break;
-      }
-      case FeedbackSlotKind::kForIn: {
-        ForInICNexus nexus(this, slot);
-        os << Code::ICState2String(nexus.StateFromFeedback());
-        break;
-      }
-      case FeedbackSlotKind::kInstanceOf: {
-        InstanceOfICNexus nexus(this, slot);
-        os << Code::ICState2String(nexus.StateFromFeedback());
-        break;
-      }
-      case FeedbackSlotKind::kStoreDataPropertyInLiteral: {
-        StoreDataPropertyInLiteralICNexus nexus(this, slot);
-        os << Code::ICState2String(nexus.StateFromFeedback());
-        break;
-      }
-      case FeedbackSlotKind::kCreateClosure:
-      case FeedbackSlotKind::kLiteral:
-      case FeedbackSlotKind::kTypeProfile:
-        break;
-      case FeedbackSlotKind::kInvalid:
-      case FeedbackSlotKind::kKindsNumber:
-        UNREACHABLE();
-        break;
-    }
+    os << "\n Slot " << slot << " " << kind << " ";
+    FeedbackSlotPrint(os, slot, kind);
 
     int entry_size = iter.entry_size();
     for (int i = 0; i < entry_size; i++) {
@@ -830,6 +757,85 @@ void FeedbackVector::FeedbackVectorPrint(std::ostream& os) {  // NOLINT
   os << "\n";
 }
 
+void FeedbackVector::FeedbackSlotPrint(std::ostream& os,
+                                       FeedbackSlot slot) {  // NOLINT
+  FeedbackSlotPrint(os, slot, GetKind(slot));
+}
+
+void FeedbackVector::FeedbackSlotPrint(std::ostream& os, FeedbackSlot slot,
+                                       FeedbackSlotKind kind) {  // NOLINT
+  switch (kind) {
+    case FeedbackSlotKind::kLoadProperty: {
+      LoadICNexus nexus(this, slot);
+      os << Code::ICState2String(nexus.StateFromFeedback());
+      break;
+    }
+    case FeedbackSlotKind::kLoadGlobalInsideTypeof:
+    case FeedbackSlotKind::kLoadGlobalNotInsideTypeof: {
+      LoadGlobalICNexus nexus(this, slot);
+      os << Code::ICState2String(nexus.StateFromFeedback());
+      break;
+    }
+    case FeedbackSlotKind::kLoadKeyed: {
+      KeyedLoadICNexus nexus(this, slot);
+      os << Code::ICState2String(nexus.StateFromFeedback());
+      break;
+    }
+    case FeedbackSlotKind::kCall: {
+      CallICNexus nexus(this, slot);
+      os << Code::ICState2String(nexus.StateFromFeedback());
+      break;
+    }
+    case FeedbackSlotKind::kStoreNamedSloppy:
+    case FeedbackSlotKind::kStoreNamedStrict:
+    case FeedbackSlotKind::kStoreOwnNamed:
+    case FeedbackSlotKind::kStoreGlobalSloppy:
+    case FeedbackSlotKind::kStoreGlobalStrict: {
+      StoreICNexus nexus(this, slot);
+      os << Code::ICState2String(nexus.StateFromFeedback());
+      break;
+    }
+    case FeedbackSlotKind::kStoreKeyedSloppy:
+    case FeedbackSlotKind::kStoreKeyedStrict: {
+      KeyedStoreICNexus nexus(this, slot);
+      os << Code::ICState2String(nexus.StateFromFeedback());
+      break;
+    }
+    case FeedbackSlotKind::kBinaryOp: {
+      BinaryOpICNexus nexus(this, slot);
+      os << "BinaryOp:" << nexus.GetBinaryOperationFeedback();
+      break;
+    }
+    case FeedbackSlotKind::kCompareOp: {
+      CompareICNexus nexus(this, slot);
+      os << "CompareOp:" << nexus.GetCompareOperationFeedback();
+      break;
+    }
+    case FeedbackSlotKind::kForIn: {
+      ForInICNexus nexus(this, slot);
+      os << "ForIn:" << nexus.GetForInFeedback();
+      break;
+    }
+    case FeedbackSlotKind::kInstanceOf: {
+      InstanceOfICNexus nexus(this, slot);
+      os << Code::ICState2String(nexus.StateFromFeedback());
+      break;
+    }
+    case FeedbackSlotKind::kStoreDataPropertyInLiteral: {
+      StoreDataPropertyInLiteralICNexus nexus(this, slot);
+      os << Code::ICState2String(nexus.StateFromFeedback());
+      break;
+    }
+    case FeedbackSlotKind::kCreateClosure:
+    case FeedbackSlotKind::kLiteral:
+    case FeedbackSlotKind::kTypeProfile:
+      break;
+    case FeedbackSlotKind::kInvalid:
+    case FeedbackSlotKind::kKindsNumber:
+      UNREACHABLE();
+      break;
+  }
+}
 
 void JSValue::JSValuePrint(std::ostream& os) {  // NOLINT
   JSObjectPrintHeader(os, this, "JSValue");

src/objects.cc

@@ -13986,7 +13986,8 @@ void JSFunction::ClearTypeFeedbackInfo() {
     FeedbackVector* vector = feedback_vector();
     Isolate* isolate = GetIsolate();
     if (vector->ClearSlots(isolate)) {
-      IC::OnFeedbackChanged(isolate, vector, this);
+      IC::OnFeedbackChanged(isolate, vector, FeedbackSlot::Invalid(), this,
+                            "ClearTypeFeedbackInfo");
     }
   }
 }

src/runtime/runtime-interpreter.cc

@@ -173,5 +173,40 @@ RUNTIME_FUNCTION(Runtime_InterpreterTraceBytecodeExit) {
 
 #endif
 
+#ifdef V8_TRACE_FEEDBACK_UPDATES
+
+RUNTIME_FUNCTION(Runtime_InterpreterTraceUpdateFeedback) {
+  if (!FLAG_trace_feedback_updates) {
+    return isolate->heap()->undefined_value();
+  }
+
+  SealHandleScope shs(isolate);
+  DCHECK_EQ(3, args.length());
+  CONVERT_ARG_HANDLE_CHECKED(JSFunction, function, 0);
+  CONVERT_SMI_ARG_CHECKED(slot, 1);
+  CONVERT_ARG_CHECKED(String, reason, 2);
+
+  int slot_count = function->feedback_vector()->metadata()->slot_count();
+
+  OFStream os(stdout);
+  os << "[Feedback slot " << slot << "/" << slot_count << " in ";
+  function->shared()->ShortPrint(os);
+  os << " updated to ";
+  function->feedback_vector()->FeedbackSlotPrint(os, FeedbackSlot(slot));
+  os << " - ";
+
+  StringCharacterStream stream(reason);
+  while (stream.HasMore()) {
+    uint16_t character = stream.GetNext();
+    PrintF("%c", character);
+  }
+
+  os << "]" << std::endl;
+
+  return isolate->heap()->undefined_value();
+}
+
+#endif
+
 }  // namespace internal
 }  // namespace v8

src/runtime/runtime.h

@@ -214,8 +214,16 @@ namespace internal {
 #define FOR_EACH_INTRINSIC_INTERPRETER_TRACE(F)
 #endif
 
-#define FOR_EACH_INTRINSIC_INTERPRETER(F) \
-  FOR_EACH_INTRINSIC_INTERPRETER_TRACE(F) \
+#ifdef V8_TRACE_FEEDBACK_UPDATES
+#define FOR_EACH_INTRINSIC_INTERPRETER_TRACE_FEEDBACK(F) \
+  F(InterpreterTraceUpdateFeedback, 3, 1)
+#else
+#define FOR_EACH_INTRINSIC_INTERPRETER_TRACE_FEEDBACK(F)
+#endif
+
+#define FOR_EACH_INTRINSIC_INTERPRETER(F)          \
+  FOR_EACH_INTRINSIC_INTERPRETER_TRACE(F)          \
+  FOR_EACH_INTRINSIC_INTERPRETER_TRACE_FEEDBACK(F) \
   F(InterpreterNewClosure, 4, 1)
 
 #define FOR_EACH_INTRINSIC_FUNCTION(F)     \