[log] Use log for --trace-maps

This is an intermediate CL to move the complete --trace-map infrastructure to
a log-based version.

Change-Id: I0673052b1b87fe338e38dc609434a52af6a0652d
Reviewed-on: https://chromium-review.googlesource.com/738835
Commit-Queue: Camillo Bruni <cbruni@chromium.org>
Reviewed-by: Jakob Kummerow <jkummerow@chromium.org>
Cr-Commit-Position: refs/heads/master@{#48988}

src/bootstrapper.cc

@@ -5353,14 +5353,13 @@ Genesis::Genesis(
     isolate->set_context(*native_context());
     isolate->counters()->contexts_created_by_snapshot()->Increment();
     if (FLAG_trace_maps) {
+      DisallowHeapAllocation no_gc;
       Handle<JSFunction> object_fun = isolate->object_function();
-      int sfi_id = -1;
-#if V8_SFI_HAS_UNIQUE_ID
-      sfi_id = object_fun->shared()->unique_id();
-#endif  // V8_SFI_HAS_UNIQUE_ID
-      PrintF("[TraceMap: InitialMap map= %p SFI= %d_Object ]\n",
-             reinterpret_cast<void*>(object_fun->initial_map()), sfi_id);
-      Map::TraceAllTransitions(object_fun->initial_map());
+      Map* initial_map = object_fun->initial_map();
+      LOG(isolate, MapDetails(initial_map));
+      LOG(isolate, MapEvent("InitialMap", nullptr, initial_map, "Object",
+                            object_fun->shared()));
+      LOG(isolate, LogAllTransitions(initial_map));
     }
 
     if (context_snapshot_index == 0) {

src/flag-definitions.h

@@ -873,6 +873,7 @@ DEFINE_BOOL(trace_prototype_users, false,
 DEFINE_BOOL(use_verbose_printer, true, "allows verbose printing")
 DEFINE_BOOL(trace_for_in_enumerate, false, "Trace for-in enumerate slow-paths")
 DEFINE_BOOL(trace_maps, false, "trace map creation")
+DEFINE_IMPLICATION(trace_maps, log_code)
 
 // parser.cc
 DEFINE_BOOL(allow_natives_syntax, false, "allow natives syntax")

src/log-utils.cc

@@ -139,6 +139,7 @@ void Log::MessageBuilder::AppendString(String* str) {
 }
 
 void Log::MessageBuilder::AppendString(const char* string) {
+  if (string == nullptr) return;
   for (const char* p = string; *p != '\0'; p++) {
     this->AppendCharacter(*p);
   }

src/log.cc

@@ -1352,6 +1352,65 @@ void Logger::ICEvent(const char* type, bool keyed, Map* map, Object* key,
   msg.WriteToLogFile();
 }
 
+void Logger::LogAllTransitions(Map* map) {
+  DisallowHeapAllocation no_gc;
+  if (!log_->IsEnabled() || !FLAG_trace_maps) return;
+  TransitionsAccessor transitions(map, &no_gc);
+  int num_transitions = transitions.NumberOfTransitions();
+  for (int i = 0; i < num_transitions; ++i) {
+    Map* target = transitions.GetTarget(i);
+    Name* key = transitions.GetKey(i);
+    MapDetails(target);
+    MapEvent("Transition", map, target, nullptr, key);
+    LogAllTransitions(target);
+  }
+}
+
+void Logger::MapEvent(const char* type, Map* from, Map* to, const char* reason,
+                      HeapObject* name_or_sfi) {
+  DisallowHeapAllocation no_gc;
+  if (!log_->IsEnabled() || !FLAG_trace_maps) return;
+  // TODO(cbruni): Remove once --trace-maps is fully migrated.
+  if (from) MapDetails(from);
+  if (to) MapDetails(to);
+  int line = -1;
+  int column = -1;
+  Address pc = 0;
+  if (!isolate_->bootstrapper()->IsActive()) {
+    pc = isolate_->GetAbstractPC(&line, &column);
+  }
+  Log::MessageBuilder msg(log_);
+  msg << "map" << kNext << type << kNext << timer_.Elapsed().InMicroseconds()
+      << kNext << reinterpret_cast<void*>(from) << kNext
+      << reinterpret_cast<void*>(to) << kNext << reinterpret_cast<void*>(pc)
+      << kNext << line << kNext << column << kNext << reason << kNext;
+
+  if (name_or_sfi) {
+    if (name_or_sfi->IsName()) {
+      msg << Name::cast(name_or_sfi);
+    } else if (name_or_sfi->IsSharedFunctionInfo()) {
+      SharedFunctionInfo* sfi = SharedFunctionInfo::cast(name_or_sfi);
+      msg << sfi->DebugName();
+#if V8_SFI_HAS_UNIQUE_ID
+      msg << " " << sfi->unique_id();
+#endif  // V8_SFI_HAS_UNIQUE_ID
+    }
+  }
+  msg.WriteToLogFile();
+}
+
+void Logger::MapDetails(Map* map) {
+  if (!log_->IsEnabled() || !FLAG_trace_maps) return;
+  DisallowHeapAllocation no_gc;
+  Log::MessageBuilder msg(log_);
+  msg << "map-details" << kNext << timer_.Elapsed().InMicroseconds() << kNext
+      << reinterpret_cast<void*>(map) << kNext;
+  std::ostringstream buffer;
+  map->PrintMapDetails(buffer);
+  msg << buffer.str().c_str();
+  msg.WriteToLogFile();
+}
+
 void Logger::StopProfiler() {
   if (!log_->IsEnabled()) return;
   if (profiler_ != nullptr) {

src/log.h

@@ -195,6 +195,12 @@ class Logger : public CodeEventListener {
                char old_state, char new_state, const char* modifier,
                const char* slow_stub_reason);
 
+  void LogAllTransitions(Map* map);
+  void MapEvent(const char* type, Map* from, Map* to,
+                const char* reason = nullptr,
+                HeapObject* name_or_sfi = nullptr);
+  void MapDetails(Map* map);
+
   // ==== Events logged by --log-gc. ====
   // Heap sampling events: start, end, and individual types.
   void HeapSampleBeginEvent(const char* space, const char* kind);

src/objects-inl.h

@@ -3419,6 +3419,9 @@ bool Map::is_callable() const {
 
 void Map::deprecate() {
   set_bit_field3(Deprecated::update(bit_field3(), true));
+  if (FLAG_trace_maps) {
+    LOG(GetIsolate(), MapEvent("Deprecate", this, nullptr));
+  }
 }
 
 bool Map::is_deprecated() const { return Deprecated::decode(bit_field3()); }

src/objects-printer.cc

@@ -1652,29 +1652,20 @@ int Name::NameShortPrint(Vector<char> str) {
   }
 }
 
-#if defined(DEBUG) || defined(OBJECT_PRINT)
-// This method is only meant to be called from gdb for debugging purposes.
-// Since the string can also be in two-byte encoding, non-Latin1 characters
-// will be ignored in the output.
-char* String::ToAsciiArray() {
-  // Static so that subsequent calls frees previously allocated space.
-  // This also means that previous results will be overwritten.
-  static char* buffer = nullptr;
-  if (buffer != nullptr) delete[] buffer;
-  buffer = new char[length() + 1];
-  WriteToFlat(this, reinterpret_cast<uint8_t*>(buffer), 0, length());
-  buffer[length()] = 0;
-  return buffer;
-}
-
-
-void DescriptorArray::Print() {
-  OFStream os(stdout);
-  this->PrintDescriptors(os);
-  os << std::flush;
+void Map::PrintMapDetails(std::ostream& os, JSObject* holder) {
+  DisallowHeapAllocation no_gc;
+#ifdef OBJECT_PRINT
+  this->MapPrint(os);
+#else
+  os << "Map=" << reinterpret_cast<void*>(this);
+#endif
+  os << "\n";
+  instance_descriptors()->PrintDescriptors(os);
+  if (is_dictionary_map() && holder != nullptr) {
+    os << holder->property_dictionary() << "\n";
+  }
 }
 
-
 void DescriptorArray::PrintDescriptors(std::ostream& os) {  // NOLINT
   HandleScope scope(GetIsolate());
   os << "Descriptor array #" << number_of_descriptors() << ":";
@@ -1715,6 +1706,26 @@ void DescriptorArray::PrintDescriptorDetails(std::ostream& os, int descriptor,
   }
 }
 
+#if defined(DEBUG) || defined(OBJECT_PRINT)
+// This method is only meant to be called from gdb for debugging purposes.
+// Since the string can also be in two-byte encoding, non-Latin1 characters
+// will be ignored in the output.
+char* String::ToAsciiArray() {
+  // Static so that subsequent calls frees previously allocated space.
+  // This also means that previous results will be overwritten.
+  static char* buffer = nullptr;
+  if (buffer != nullptr) delete[] buffer;
+  buffer = new char[length() + 1];
+  WriteToFlat(this, reinterpret_cast<uint8_t*>(buffer), 0, length());
+  buffer[length()] = 0;
+  return buffer;
+}
+
+void DescriptorArray::Print() {
+  OFStream os(stdout);
+  this->PrintDescriptors(os);
+  os << std::flush;
+}
 // static
 void TransitionsAccessor::PrintOneTransition(std::ostream& os, Name* key,
                                              Map* target, Object* raw_target) {

src/objects.cc

@@ -6219,9 +6219,7 @@ void JSObject::MigrateSlowToFast(Handle<JSObject> object,
   NotifyMapChange(old_map, new_map, isolate);
 
   if (FLAG_trace_maps) {
-    PrintF("[TraceMaps: SlowToFast from= %p to= %p reason= %s ]\n",
-           reinterpret_cast<void*>(*old_map), reinterpret_cast<void*>(*new_map),
-           reason);
+    LOG(isolate, MapEvent("SlowToFast", *old_map, *new_map, reason));
   }
 
   if (instance_descriptor_length == 0) {
@@ -9040,9 +9038,7 @@ Handle<Map> Map::Normalize(Handle<Map> fast_map, PropertyNormalizationMode mode,
       isolate->counters()->maps_normalized()->Increment();
     }
     if (FLAG_trace_maps) {
-      PrintF("[TraceMaps: Normalize from= %p to= %p reason= %s ]\n",
-             reinterpret_cast<void*>(*fast_map),
-             reinterpret_cast<void*>(*new_map), reason);
+      LOG(isolate, MapEvent("Normalize", *fast_map, *new_map, reason));
     }
   }
   fast_map->NotifyLeafMapLayoutChange();
@@ -9208,30 +9204,6 @@ Handle<Map> Map::ShareDescriptor(Handle<Map> map,
   return result;
 }
 
-// static
-void Map::TraceTransition(const char* what, Map* from, Map* to, Name* name) {
-  if (FLAG_trace_maps) {
-    PrintF("[TraceMaps: %s from= %p to= %p name= ", what,
-           reinterpret_cast<void*>(from), reinterpret_cast<void*>(to));
-    name->NameShortPrint();
-    PrintF(" ]\n");
-  }
-}
-
-
-// static
-void Map::TraceAllTransitions(Map* map) {
-  DisallowHeapAllocation no_gc;
-  TransitionsAccessor transitions(map, &no_gc);
-  int num_transitions = transitions.NumberOfTransitions();
-  for (int i = -0; i < num_transitions; ++i) {
-    Map* target = transitions.GetTarget(i);
-    Name* key = transitions.GetKey(i);
-    Map::TraceTransition("Transition", map, target, key);
-    Map::TraceAllTransitions(target);
-  }
-}
-
 void Map::ConnectTransition(Handle<Map> parent, Handle<Map> child,
                             Handle<Name> name, SimpleTransitionFlag flag) {
   Isolate* isolate = parent->GetIsolate();
@@ -9255,10 +9227,14 @@ void Map::ConnectTransition(Handle<Map> parent, Handle<Map> child,
   }
   if (parent->is_prototype_map()) {
     DCHECK(child->is_prototype_map());
-    Map::TraceTransition("NoTransition", *parent, *child, *name);
+    if (FLAG_trace_maps) {
+      LOG(isolate, MapEvent("Transition", *parent, *child, "prototype", *name));
+    }
   } else {
     TransitionsAccessor(parent).Insert(name, child, flag);
-    Map::TraceTransition("Transition", *parent, *child, *name);
+    if (FLAG_trace_maps) {
+      LOG(isolate, MapEvent("Transition", *parent, *child, "", *name));
+    }
   }
 }
 
@@ -9298,9 +9274,8 @@ Handle<Map> Map::CopyReplaceDescriptors(
       (map->is_prototype_map() ||
        !(flag == INSERT_TRANSITION &&
          TransitionsAccessor(map).CanHaveMoreTransitions()))) {
-    PrintF("[TraceMaps: ReplaceDescriptors from= %p to= %p reason= %s ]\n",
-           reinterpret_cast<void*>(*map), reinterpret_cast<void*>(*result),
-           reason);
+    LOG(map->GetIsolate(), MapEvent("ReplaceDescriptors", *map, *result, reason,
+                                    maybe_name.is_null() ? nullptr : *name));
   }
   return result;
 }
@@ -9488,11 +9463,9 @@ Handle<Map> Map::CopyForTransition(Handle<Map> map, const char* reason) {
   }
 
   if (FLAG_trace_maps) {
-    PrintF("[TraceMaps: CopyForTransition from= %p to= %p reason= %s ]\n",
-           reinterpret_cast<void*>(*map), reinterpret_cast<void*>(*new_map),
-           reason);
+    LOG(map->GetIsolate(),
+        MapEvent("CopyForTransition", *map, *new_map, reason));
   }
-
   return new_map;
 }
 
@@ -12743,13 +12716,8 @@ void JSFunction::SetInitialMap(Handle<JSFunction> function, Handle<Map> map,
   function->set_prototype_or_initial_map(*map);
   map->SetConstructor(*function);
   if (FLAG_trace_maps) {
-    int sfi_id = -1;
-#if V8_SFI_HAS_UNIQUE_ID
-    sfi_id = function->shared()->unique_id();
-#endif  // V8_SFI_HAS_UNIQUE_ID
-    PrintF("[TraceMaps: InitialMap map= %p SFI= %d_%s ]\n",
-           reinterpret_cast<void*>(*map), sfi_id,
-           function->shared()->DebugName()->ToCString().get());
+    LOG(map->GetIsolate(), MapEvent("InitialMap", nullptr, *map, "",
+                                    function->shared()->DebugName()));
   }
 }
 

src/objects/descriptor-array.h

@@ -141,15 +141,14 @@ class DescriptorArray : public FixedArray {
   static const int kEntryValueIndex = 2;
   static const int kEntrySize = 3;
 
-#if defined(DEBUG) || defined(OBJECT_PRINT)
-  // For our gdb macros, we should perhaps change these in the future.
-  void Print();
-
   // Print all the descriptors.
   void PrintDescriptors(std::ostream& os);  // NOLINT
-
   void PrintDescriptorDetails(std::ostream& os, int descriptor,
                               PropertyDetails::PrintMode mode);
+
+#if defined(DEBUG) || defined(OBJECT_PRINT)
+  // For our gdb macros, we should perhaps change these in the future.
+  void Print();
 #endif
 
 #ifdef DEBUG

src/objects/map.h

@@ -833,8 +833,7 @@ class Map : public HeapObject {
   // Returns true if given field is unboxed double.
   inline bool IsUnboxedDoubleField(FieldIndex index) const;
 
-  static void TraceTransition(const char* what, Map* from, Map* to, Name* name);
-  static void TraceAllTransitions(Map* map);
+  void PrintMapDetails(std::ostream& os, JSObject* holder = nullptr);
 
   static inline Handle<Map> AddMissingTransitionsForTesting(
       Handle<Map> split_map, Handle<DescriptorArray> descriptors,

test/cctest/test-log.cc

@@ -697,3 +697,34 @@ TEST(LogAll) {
   }
   isolate->Dispose();
 }
+
+TEST(TraceMaps) {
+  SETUP_FLAGS();
+  i::FLAG_trace_maps = true;
+  v8::Isolate::CreateParams create_params;
+  create_params.array_buffer_allocator = CcTest::array_buffer_allocator();
+  v8::Isolate* isolate = v8::Isolate::New(create_params);
+  {
+    ScopedLoggerInitializer logger(saved_log, saved_prof, isolate);
+    // Try to create many different kind of maps to make sure the logging won't
+    // crash. More detailed tests are implemented separately.
+    const char* source_text =
+        "let a = {};"
+        "for (let i = 0; i < 500; i++) { a['p'+i] = i };"
+        "class Test { constructor(i) { this.a = 1; this['p'+i] = 1; }};"
+        "let t = new Test();"
+        "t.b = 1; t.c = 1; t.d = 3;"
+        "for (let i = 0; i < 100; i++) { t = new Test(i) };"
+        "t.b = {};";
+    CompileRun(source_text);
+
+    logger.StopLogging();
+
+    // Mostly superficial checks.
+    CHECK(logger.FindLine("map,InitialMap", ",0x"));
+    CHECK(logger.FindLine("map,Transition", ",0x"));
+    CHECK(logger.FindLine("map-details", ",0x"));
+  }
+  i::FLAG_trace_maps = false;
+  isolate->Dispose();
+}