[turbofan] Clean up broker tracing, part 1

Make the tracing code and output more consistent and/or compact.

Also, restrict --trace-heap-broker to reports about missing data and
introduce a new flag --trace-heap-broker-verbose that prints everything.

Bug: v8:7790
Change-Id: I6e678fb97bf8631428594f77d8b5f0909ab2e281
Reviewed-on: https://chromium-review.googlesource.com/c/v8/v8/+/1559864Reviewed-by: Maya Lekova <mslekova@chromium.org>
Commit-Queue: Georg Neis <neis@chromium.org>
Cr-Commit-Position: refs/heads/master@{#60745}

src/compiler/access-info.cc

@@ -260,18 +260,10 @@ bool AccessInfoFactory::ComputeElementAccessInfo(
 bool AccessInfoFactory::ComputeElementAccessInfos(
     FeedbackNexus nexus, MapHandles const& maps, AccessMode access_mode,
     ZoneVector<ElementAccessInfo>* access_infos) const {
-  ElementAccessFeedback const* processed;
-  if (FLAG_concurrent_inlining) {
-    TRACE_BROKER(broker(),
-                 "ComputeElementAccessInfos: using preprocessed feedback "
-                     << "(slot " << nexus.slot() << " of "
-                     << "feedback vector handle "
-                     << nexus.vector_handle().address() << ").\n");
-    processed = broker()->GetElementAccessFeedback(FeedbackSource(nexus));
-  } else {
-    processed = broker()->ProcessFeedbackMapsForElementAccess(maps);
-  }
-
+  ElementAccessFeedback const* processed =
+      FLAG_concurrent_inlining
+          ? broker()->GetElementAccessFeedback(FeedbackSource(nexus))
+          : broker()->ProcessFeedbackMapsForElementAccess(maps);
   if (processed == nullptr) return false;
 
   if (access_mode == AccessMode::kLoad || access_mode == AccessMode::kHas) {

src/compiler/js-heap-broker.cc

@@ -31,6 +31,7 @@ namespace internal {
 namespace compiler {
 
 #define TRACE(broker, x) TRACE_BROKER(broker, x)
+#define TRACE_MISSING(broker, x) TRACE_BROKER_MISSING(broker, x)
 
 #define FORWARD_DECL(Name) class Name##Data;
 HEAP_BROKER_OBJECT_LIST(FORWARD_DECL)
@@ -135,7 +136,7 @@ class TraceScope {
 
   TraceScope(JSHeapBroker* broker, void* self, const char* label)
       : broker_(broker) {
-    TRACE(broker_, "Running " << label << " on " << self << ".");
+    TRACE(broker_, "Running " << label << " on " << self);
     broker_->IncrementTracingIndentation();
   }
 };
@@ -268,8 +269,7 @@ ObjectData* JSObjectData::GetOwnConstantElement(JSHeapBroker* broker,
   }
 
   if (!serialize) {
-    TRACE(broker, "GetOwnConstantElement: missing index "
-                      << index << " on data " << this << "\n");
+    TRACE_MISSING(broker, "knowledge about index " << index << " on " << this);
     return nullptr;
   }
 
@@ -493,7 +493,7 @@ void ContextData::SerializeContextChain(JSHeapBroker* broker) {
 
 void ContextData::SerializeSlot(JSHeapBroker* broker, int index) {
   TraceScope tracer(broker, this, "ContextData::SerializeSlot");
-  TRACE(broker, "Serializing script context slot " << index << ".");
+  TRACE(broker, "Serializing script context slot " << index);
   Handle<Context> context = Handle<Context>::cast(object());
   CHECK(index >= 0 && index < context->length());
   ObjectData* odata = broker->GetOrCreateData(context->get(index));
@@ -598,8 +598,7 @@ StringData* StringData::GetCharAsString(JSHeapBroker* broker, uint32_t index,
   }
 
   if (!serialize) {
-    TRACE(broker, "GetCharAsString: missing index " << index << " on data "
-                                                    << this << "\n");
+    TRACE_MISSING(broker, "knowledge about index " << index << " on " << this);
     return nullptr;
   }
 
@@ -1074,7 +1073,7 @@ void FeedbackVectorData::SerializeSlots(JSHeapBroker* broker) {
     }
   }
   DCHECK_EQ(vector->length(), feedback_.size());
-  TRACE(broker, "Copied " << feedback_.size() << " slots.");
+  TRACE(broker, "Copied " << feedback_.size() << " slots");
 }
 
 class FixedArrayBaseData : public HeapObjectData {
@@ -1159,7 +1158,7 @@ void FixedArrayData::SerializeContents(JSHeapBroker* broker) {
     Handle<Object> value(array->get(i), broker->isolate());
     contents_.push_back(broker->GetOrCreateData(value));
   }
-  TRACE(broker, "Copied " << contents_.size() << " elements.");
+  TRACE(broker, "Copied " << contents_.size() << " elements");
 }
 
 class FixedDoubleArrayData : public FixedArrayBaseData {
@@ -1195,7 +1194,7 @@ void FixedDoubleArrayData::SerializeContents(JSHeapBroker* broker) {
   for (int i = 0; i < length(); i++) {
     contents_.push_back(Float64::FromBits(self->get_representation(i)));
   }
-  TRACE(broker, "Copied " << contents_.size() << " elements.");
+  TRACE(broker, "Copied " << contents_.size() << " elements");
 }
 
 class BytecodeArrayData : public FixedArrayBaseData {
@@ -1255,8 +1254,7 @@ ObjectData* JSArrayData::GetOwnElement(JSHeapBroker* broker, uint32_t index,
   }
 
   if (!serialize) {
-    TRACE(broker, "GetOwnElement: missing index " << index << " on data "
-                                                  << this << "\n");
+    TRACE_MISSING(broker, "knowledge about index " << index << " on " << this);
     return nullptr;
   }
 
@@ -1333,7 +1331,7 @@ void SharedFunctionInfoData::SetSerializedForCompilation(
     JSHeapBroker* broker, FeedbackVectorRef feedback) {
   CHECK(serialized_for_compilation_.insert(feedback.object()).second);
   TRACE(broker, "Set function " << object() << " with " << feedback.object()
-                                << " as serialized for compilation.");
+                                << " as serialized for compilation");
 }
 
 bool SharedFunctionInfoData::IsSerializedForCompilation(
@@ -1396,7 +1394,7 @@ void ModuleData::Serialize(JSHeapBroker* broker) {
   for (int i = 0; i < imports_length; ++i) {
     imports_.push_back(broker->GetOrCreateData(imports->get(i))->AsCell());
   }
-  TRACE(broker, "Copied " << imports_.size() << " imports.");
+  TRACE(broker, "Copied " << imports_.size() << " imports");
 
   DCHECK(exports_.empty());
   Handle<FixedArray> exports(module->regular_exports(), broker->isolate());
@@ -1405,7 +1403,7 @@ void ModuleData::Serialize(JSHeapBroker* broker) {
   for (int i = 0; i < exports_length; ++i) {
     exports_.push_back(broker->GetOrCreateData(exports->get(i))->AsCell());
   }
-  TRACE(broker, "Copied " << exports_.size() << " exports.");
+  TRACE(broker, "Copied " << exports_.size() << " exports");
 }
 
 class CellData : public HeapObjectData {
@@ -1479,11 +1477,7 @@ PropertyCellData* JSGlobalProxyData::GetPropertyCell(JSHeapBroker* broker,
   }
 
   if (!serialize) {
-    AllowHandleAllocation handle_allocation_;
-    AllowHandleDereference handle_dereference_;
-    AllowHeapAllocation heap_allocation_;
-    TRACE(broker, "GetPropertyCell: missing knowledge about global property "
-                      << Brief(*name->object()) << "\n");
+    TRACE_MISSING(broker, "knowledge about global property " << name);
     return nullptr;
   }
 
@@ -1622,7 +1616,7 @@ void MapData::SerializeOwnDescriptors(JSHeapBroker* broker) {
 
   TRACE(broker, "Copied " << number_of_own - current_size
                           << " descriptors into " << instance_descriptors_
-                          << " (" << number_of_own << " total).");
+                          << " (" << number_of_own << " total)");
 }
 
 void JSObjectData::SerializeRecursive(JSHeapBroker* broker, int depth) {
@@ -1716,7 +1710,7 @@ void JSObjectData::SerializeRecursive(JSHeapBroker* broker, int depth) {
       inobject_fields_.push_back(JSObjectField{value_data});
     }
   }
-  TRACE(broker, "Copied " << inobject_fields_.size() << " in-object fields.");
+  TRACE(broker, "Copied " << inobject_fields_.size() << " in-object fields");
 
   map()->SerializeOwnDescriptors(broker);
 
@@ -1780,7 +1774,7 @@ JSHeapBroker::JSHeapBroker(Isolate* isolate, Zone* broker_zone)
   // compilation enabled, standard objects to be serialized), as the map
   // is going to be replaced immediatelly with a larger capacity one.
   // It doesn't seem to affect the performance in a noticeable way though.
-  TRACE(this, "Constructing heap broker.");
+  TRACE(this, "Constructing heap broker");
 }
 
 std::ostream& JSHeapBroker::Trace() {
@@ -1790,20 +1784,20 @@ std::ostream& JSHeapBroker::Trace() {
 
 void JSHeapBroker::StartSerializing() {
   CHECK_EQ(mode_, kDisabled);
-  TRACE(this, "Starting serialization.");
+  TRACE(this, "Starting serialization");
   mode_ = kSerializing;
   refs_->Clear();
 }
 
 void JSHeapBroker::StopSerializing() {
   CHECK_EQ(mode_, kSerializing);
-  TRACE(this, "Stopping serialization.");
+  TRACE(this, "Stopping serialization");
   mode_ = kSerialized;
 }
 
 void JSHeapBroker::Retire() {
   CHECK_EQ(mode_, kSerialized);
-  TRACE(this, "Retiring.");
+  TRACE(this, "Retiring");
   mode_ = kRetired;
 }
 
@@ -2008,7 +2002,7 @@ void JSHeapBroker::SerializeStandardObjects() {
   GetOrCreateData(
       CodeFactory::CEntry(isolate(), 1, kDontSaveFPRegs, kArgvOnStack, true));
 
-  TRACE(this, "Finished serializing standard objects.");
+  TRACE(this, "Finished serializing standard objects");
 }
 
 ObjectData* JSHeapBroker::GetData(Handle<Object> object) const {
@@ -2743,8 +2737,7 @@ base::Optional<ObjectRef> JSArrayRef::GetOwnCowElement(uint32_t index,
   if (serialize) {
     data()->AsJSObject()->SerializeElements(broker());
   } else if (!data()->AsJSObject()->serialized_elements()) {
-    TRACE(broker(),
-          "GetOwnCowElement: missing 'elements' on data " << this << ".\n");
+    TRACE(broker(), "'elements' on data " << this);
     return base::nullopt;
   }
   if (!elements().map().IsFixedCowArrayMap()) return base::nullopt;
@@ -2948,10 +2941,7 @@ ObjectData* ObjectRef::data() const {
 
 Reduction NoChangeBecauseOfMissingData(JSHeapBroker* broker,
                                        const char* function, int line) {
-  if (FLAG_trace_heap_broker) {
-    PrintF("[%p] Skipping optimization in %s at line %d due to missing data\n",
-           broker, function, line);
-  }
+  TRACE_MISSING(broker, "data in function " << function << " at line " << line);
   return AdvancedReducer::NoChange();
 }
 
@@ -3336,12 +3326,17 @@ GlobalAccessFeedback const* JSHeapBroker::ProcessFeedbackForGlobalAccess(
   return new (zone()) GlobalAccessFeedback(cell);
 }
 
+std::ostream& operator<<(std::ostream& os, const ObjectRef& ref) {
+  return os << ref.data();
+}
+
 #undef BIMODAL_ACCESSOR
 #undef BIMODAL_ACCESSOR_B
 #undef BIMODAL_ACCESSOR_C
 #undef IF_BROKER_DISABLED_ACCESS_HANDLE
 #undef IF_BROKER_DISABLED_ACCESS_HANDLE_C
 #undef TRACE
+#undef TRACE_MISSING
 
 }  // namespace compiler
 }  // namespace internal

src/compiler/js-heap-broker.h

@@ -143,9 +143,13 @@ class V8_EXPORT_PRIVATE ObjectRef {
   friend class JSObjectData;
   friend class StringData;
 
+  friend std::ostream& operator<<(std::ostream& os, const ObjectRef& ref);
+
   JSHeapBroker* broker_;
 };
 
+std::ostream& operator<<(std::ostream& os, const ObjectRef& ref);
+
 // Temporary class that carries information from a Map. We'd like to remove
 // this class and use MapRef instead, but we can't as long as we support the
 // kDisabled broker mode. That's because obtaining the MapRef via
@@ -836,9 +840,15 @@ Reduction NoChangeBecauseOfMissingData(JSHeapBroker* broker,
 // compilation is finished.
 bool CanInlineElementAccess(MapRef const& map);
 
-#define TRACE_BROKER(broker, x)                               \
-  do {                                                        \
-    if (FLAG_trace_heap_broker) broker->Trace() << x << '\n'; \
+#define TRACE_BROKER(broker, x)                                       \
+  do {                                                                \
+    if (FLAG_trace_heap_broker_verbose) broker->Trace() << x << '\n'; \
+  } while (false)
+
+#define TRACE_BROKER_MISSING(broker, x)                             \
+  do {                                                              \
+    if (FLAG_trace_heap_broker)                                     \
+      broker->Trace() << __FUNCTION__ << ": missing " << x << '\n'; \
   } while (false)
 
 }  // namespace compiler

src/compiler/js-native-context-specialization.cc

@@ -356,8 +356,7 @@ Reduction JSNativeContextSpecialization::ReduceJSGetSuperConstructor(
   if (!FLAG_concurrent_inlining) {
     function_map.SerializePrototype();
   } else if (!function_map.serialized_prototype()) {
-    TRACE_BROKER(broker(), "ReduceJSGetSuperConstructor: missing data for map "
-                               << function_map.object().address() << "\n");
+    TRACE_BROKER_MISSING(broker(), "data for map " << function_map);
     return NoChange();
   }
   ObjectRef function_prototype = function_map.prototype();
@@ -1007,17 +1006,10 @@ Reduction JSNativeContextSpecialization::ReduceJSLoadGlobal(Node* node) {
   if (!p.feedback().IsValid()) return NoChange();
   FeedbackSource source(p.feedback());
 
-  GlobalAccessFeedback const* processed;
-  if (FLAG_concurrent_inlining) {
-    processed = broker()->GetGlobalAccessFeedback(source);
-    TRACE_BROKER(broker(), "ReduceJSLoadGlobal: using preprocessed feedback "
-                               << "(slot " << p.feedback().slot()
-                               << " of feedback vector handle "
-                               << p.feedback().vector().address() << ").\n");
-  } else {
-    processed = broker()->ProcessFeedbackForGlobalAccess(source);
-  }
-
+  GlobalAccessFeedback const* processed =
+      FLAG_concurrent_inlining
+          ? broker()->GetGlobalAccessFeedback(source)
+          : broker()->ProcessFeedbackForGlobalAccess(source);
   if (processed == nullptr) return NoChange();
 
   if (processed->IsScriptContextSlot()) {
@@ -1046,17 +1038,10 @@ Reduction JSNativeContextSpecialization::ReduceJSStoreGlobal(Node* node) {
   if (!p.feedback().IsValid()) return NoChange();
   FeedbackSource source(p.feedback());
 
-  GlobalAccessFeedback const* processed;
-  if (FLAG_concurrent_inlining) {
-    processed = broker()->GetGlobalAccessFeedback(source);
-    TRACE_BROKER(broker(), "ReduceJSStoreGlobal: using preprocessed feedback "
-                               << "(slot " << p.feedback().slot()
-                               << " of feedback vector handle "
-                               << p.feedback().vector().address() << ").\n");
-  } else {
-    processed = broker()->ProcessFeedbackForGlobalAccess(source);
-  }
-
+  GlobalAccessFeedback const* processed =
+      FLAG_concurrent_inlining
+          ? broker()->GetGlobalAccessFeedback(source)
+          : broker()->ProcessFeedbackForGlobalAccess(source);
   if (processed == nullptr) return NoChange();
 
   if (processed->IsScriptContextSlot()) {
@@ -1392,8 +1377,7 @@ Reduction JSNativeContextSpecialization::ReduceJSLoadNamed(Node* node) {
       if (!FLAG_concurrent_inlining) {
         function.Serialize();
       } else if (!function.serialized()) {
-        TRACE_BROKER(broker(), "ReduceJSLoadNamed: missing data for function "
-                                   << function.object().address() << "\n");
+        TRACE_BROKER_MISSING(broker(), "data for function " << function);
         return NoChange();
       }
       // TODO(neis): Remove the has_prototype_slot condition once the broker is
@@ -1581,9 +1565,7 @@ Reduction JSNativeContextSpecialization::ReduceElementAccess(
       if (!FLAG_concurrent_inlining) {
         typed_array->Serialize();
       } else if (!typed_array->serialized()) {
-        TRACE_BROKER(broker(),
-                     "ReduceElementAccess: missing data for typed array "
-                         << typed_array->object().address() << "\n");
+        TRACE_BROKER_MISSING(broker(), "data for typed array " << *typed_array);
         return NoChange();
       }
     }

src/compiler/serializer-for-background-compilation.cc

@@ -561,12 +561,8 @@ Hints SerializerForBackgroundCompilation::RunChildSerializer(
     return RunChildSerializer(function, new_target, padded, false);
   }
 
-  if (FLAG_trace_heap_broker) {
-    std::ostream& out = broker()->Trace();
-    out << "\nWill run child serializer with environment:\n"
-        << "===========================================\n"
-        << *environment();
-  }
+  TRACE_BROKER(broker(), "Will run child serializer with environment:\n"
+                             << *environment());
 
   SerializerForBackgroundCompilation child_serializer(
       broker(), zone(), function, new_target, arguments);

src/flag-definitions.h

@@ -429,7 +429,11 @@ DEFINE_BOOL(block_concurrent_recompilation, false,
 DEFINE_BOOL(concurrent_inlining, false,
             "run optimizing compiler's inlining phase on a separate thread")
 DEFINE_IMPLICATION(future, concurrent_inlining)
-DEFINE_BOOL(trace_heap_broker, false, "trace the heap broker")
+DEFINE_BOOL(trace_heap_broker_verbose, false,
+            "trace the heap broker verbosely (all reports)")
+DEFINE_BOOL(trace_heap_broker, false,
+            "trace the heap broker (reports on missing data only)")
+DEFINE_IMPLICATION(trace_heap_broker_verbose, trace_heap_broker)
 
 // Flags for stress-testing the compiler.
 DEFINE_INT(stress_runs, 0, "number of stress runs")