[log] Improve --trace-maps logging

Only log incrementally deserialized maps with --trace-maps instead of
iterating the whole heap and print all existing maps on every partial
deserialization for new contexts. This should greatly improve
performance of --trace-maps on websites with many iframes.

- Add helpers to share code: LogNewObjectEvents, LogScriptEvents,
  LogNewMapEvents
- Link AllocationSites before any GC

Change-Id: I5322421a83e057518f871540691511c80bc7786a
Reviewed-on: https://chromium-review.googlesource.com/c/1342029Reviewed-by: Michael Lippautz <mlippautz@chromium.org>
Reviewed-by: Jakob Gruber <jgruber@chromium.org>
Commit-Queue: Camillo Bruni <cbruni@chromium.org>
Cr-Commit-Position: refs/heads/master@{#57874}

src/bootstrapper.cc

@@ -348,8 +348,7 @@ Handle<Context> Bootstrapper::CreateEnvironment(
       return Handle<Context>();
     }
   }
-  // Log all maps created during bootstrapping.
-  if (FLAG_trace_maps) LOG(isolate_, LogMaps());
+  LogAllMaps();
   return scope.CloseAndEscape(env);
 }
 
@@ -363,11 +362,18 @@ Handle<JSGlobalProxy> Bootstrapper::NewRemoteContext(
     global_proxy = genesis.global_proxy();
     if (global_proxy.is_null()) return Handle<JSGlobalProxy>();
   }
-  // Log all maps created during bootstrapping.
-  if (FLAG_trace_maps) LOG(isolate_, LogMaps());
+  LogAllMaps();
   return scope.CloseAndEscape(global_proxy);
 }
 
+void Bootstrapper::LogAllMaps() {
+  if (!FLAG_trace_maps || isolate_->initialized_from_snapshot()) return;
+  // Log all created Map objects that are on the heap. For snapshots the Map
+  // logging happens during deserialization in order to avoid printing Maps
+  // multiple times during partial deserialization.
+  LOG(isolate_, LogAllMaps());
+}
+
 void Bootstrapper::DetachGlobal(Handle<Context> env) {
   isolate_->counters()->errors_thrown_per_context()->AddSample(
       env->GetErrorsThrown());

src/bootstrapper.h

@@ -100,6 +100,9 @@ class Bootstrapper final {
   static void ExportFromRuntime(Isolate* isolate, Handle<JSObject> container);
 
  private:
+  // Log newly created Map objects if no snapshot was used.
+  void LogAllMaps();
+
   Isolate* isolate_;
   typedef int NestingCounterType;
   NestingCounterType nesting_;

src/heap/factory.cc

@@ -2970,6 +2970,7 @@ Handle<JSGlobalObject> Factory::NewJSGlobalObject(
   Handle<Map> new_map = Map::CopyDropDescriptors(isolate(), map);
   new_map->set_may_have_interesting_symbols(true);
   new_map->set_is_dictionary_map(true);
+  LOG(isolate(), MapDetails(*new_map));
 
   // Set up the global object as a normalized object.
   global->set_global_dictionary(*dictionary);
@@ -3507,6 +3508,7 @@ Handle<JSGlobalProxy> Factory::NewUninitializedJSGlobalProxy(int size) {
   // Maintain invariant expected from any JSGlobalProxy.
   map->set_is_access_check_needed(true);
   map->set_may_have_interesting_symbols(true);
+  LOG(isolate(), MapDetails(*map));
   return Handle<JSGlobalProxy>::cast(NewJSObjectFromMap(map, NOT_TENURED));
 }
 
@@ -4087,6 +4089,7 @@ Handle<Map> Factory::CreateSloppyFunctionMap(
     map->AppendDescriptor(&d);
   }
   DCHECK_EQ(inobject_properties_count, field_index);
+  LOG(isolate(), MapDetails(*map));
   return map;
 }
 
@@ -4163,6 +4166,7 @@ Handle<Map> Factory::CreateStrictFunctionMap(
     map->AppendDescriptor(&d);
   }
   DCHECK_EQ(inobject_properties_count, field_index);
+  LOG(isolate(), MapDetails(*map));
   return map;
 }
 
@@ -4197,6 +4201,7 @@ Handle<Map> Factory::CreateClassFunctionMap(Handle<JSFunction> empty_function) {
         prototype_string(), function_prototype_accessor(), ro_attribs);
     map->AppendDescriptor(&d);
   }
+  LOG(isolate(), MapDetails(*map));
   return map;
 }
 

src/log.cc

@@ -1714,9 +1714,6 @@ void Logger::MapCreate(Map map) {
 
 void Logger::MapDetails(Map map) {
   if (!log_->IsEnabled() || !FLAG_trace_maps) return;
-  // Disable logging Map details during bootstrapping since we use LogMaps() to
-  // log all creating
-  if (isolate_->bootstrapper()->IsActive()) return;
   DisallowHeapAllocation no_gc;
   Log::MessageBuilder msg(log_);
   msg << "map-details" << kNext << timer_.Elapsed().InMicroseconds() << kNext
@@ -1860,14 +1857,16 @@ void Logger::LogAccessorCallbacks() {
   }
 }
 
-void Logger::LogMaps() {
+void Logger::LogAllMaps() {
+  DisallowHeapAllocation no_gc;
   Heap* heap = isolate_->heap();
   HeapIterator iterator(heap);
-  DisallowHeapAllocation no_gc;
   for (HeapObject* obj = iterator.next(); obj != nullptr;
        obj = iterator.next()) {
     if (!obj->IsMap()) continue;
-    MapDetails(Map::cast(obj));
+    Map map = Map::cast(obj);
+    MapCreate(map);
+    MapDetails(map);
   }
 }
 

src/log.h

@@ -274,8 +274,8 @@ class Logger : public CodeEventListener {
   void LogAccessorCallbacks();
   // Used for logging stubs found in the snapshot.
   void LogCodeObjects();
-  // Logs all Mpas foind in the heap.
-  void LogMaps();
+  // Logs all Maps found on the heap.
+  void LogAllMaps();
 
   // Converts tag to a corresponding NATIVE_... if the script is native.
   V8_INLINE static CodeEventListener::LogEventsAndTags ToNativeByScript(

src/objects.cc

@@ -6677,9 +6677,6 @@ void JSObject::MigrateSlowToFast(Handle<JSObject> object,
 
   NotifyMapChange(old_map, new_map, isolate);
 
-  if (FLAG_trace_maps) {
-    LOG(isolate, MapEvent("SlowToFast", *old_map, *new_map, reason));
-  }
 
   if (instance_descriptor_length == 0) {
     DisallowHeapAllocation no_gc;
@@ -6690,6 +6687,9 @@ void JSObject::MigrateSlowToFast(Handle<JSObject> object,
     object->SetProperties(ReadOnlyRoots(isolate).empty_fixed_array());
     // Check that it really works.
     DCHECK(object->HasFastProperties());
+    if (FLAG_trace_maps) {
+      LOG(isolate, MapEvent("SlowToFast", *old_map, *new_map, reason));
+    }
     return;
   }
 
@@ -6784,6 +6784,9 @@ void JSObject::MigrateSlowToFast(Handle<JSObject> object,
     new_map->SetOutOfObjectUnusedPropertyFields(unused_property_fields);
   }
 
+  if (FLAG_trace_maps) {
+    LOG(isolate, MapEvent("SlowToFast", *old_map, *new_map, reason));
+  }
   // Transform the object.
   object->synchronized_set_map(*new_map);
 
@@ -9695,6 +9698,7 @@ Handle<Map> Map::AddMissingTransitions(
     Handle<Map> new_map = CopyDropDescriptors(isolate, map);
     InstallDescriptors(isolate, map, new_map, i, descriptors,
                        full_layout_descriptor);
+
     map = new_map;
   }
   map->NotifyLeafMapLayoutChange(isolate);
@@ -9775,7 +9779,7 @@ Handle<Map> Map::CopyAsElementsKind(Isolate* isolate, Handle<Map> map,
       maybe_elements_transition_map.is_null();
 
   if (insert_transition) {
-    Handle<Map> new_map = CopyForTransition(isolate, map, "CopyAsElementsKind");
+    Handle<Map> new_map = CopyForElementsTransition(isolate, map);
     new_map->set_elements_kind(kind);
 
     Handle<Name> name = isolate->factory()->elements_transition_symbol();
@@ -9829,8 +9833,7 @@ Handle<Map> Map::AsLanguageMode(Isolate* isolate, Handle<Map> initial_map,
   return map;
 }
 
-Handle<Map> Map::CopyForTransition(Isolate* isolate, Handle<Map> map,
-                                   const char* reason) {
+Handle<Map> Map::CopyForElementsTransition(Isolate* isolate, Handle<Map> map) {
   DCHECK(!map->is_prototype_map());
   Handle<Map> new_map = CopyDropDescriptors(isolate, map);
 
@@ -9851,10 +9854,6 @@ Handle<Map> Map::CopyForTransition(Isolate* isolate, Handle<Map> map,
                                                    isolate);
     new_map->InitializeDescriptors(*new_descriptors, *new_layout_descriptor);
   }
-
-  if (FLAG_trace_maps) {
-    LOG(isolate, MapEvent("CopyForTransition", *map, *new_map, reason));
-  }
   return new_map;
 }
 

src/objects/map.h

@@ -735,8 +735,8 @@ class Map : public HeapObjectPtr {
   // Returns a copy of the map, prepared for inserting into the transition
   // tree (if the |map| owns descriptors then the new one will share
   // descriptors with |map|).
-  static Handle<Map> CopyForTransition(Isolate* isolate, Handle<Map> map,
-                                       const char* reason);
+  static Handle<Map> CopyForElementsTransition(Isolate* isolate,
+                                               Handle<Map> map);
 
   // Returns a copy of the map, with all transitions dropped from the
   // instance descriptors.

src/snapshot/deserializer.cc

@@ -8,6 +8,7 @@
 #include "src/heap/heap-write-barrier-inl.h"
 #include "src/interpreter/interpreter.h"
 #include "src/isolate.h"
+#include "src/log.h"
 #include "src/objects/api-callbacks.h"
 #include "src/objects/hash-table.h"
 #include "src/objects/js-array-buffer-inl.h"
@@ -152,6 +153,34 @@ void Deserializer::DeserializeDeferredObjects() {
   }
 }
 
+void Deserializer::LogNewObjectEvents() {
+  {
+    // {new_maps_} and {new_code_objects_} are vectors containing raw
+    // pointers, hence there should be no GC happening.
+    DisallowHeapAllocation no_gc;
+    // Issue code events for newly deserialized code objects.
+    LOG_CODE_EVENT(isolate_, LogCodeObjects());
+  }
+  LOG_CODE_EVENT(isolate_, LogCompiledFunctions());
+  LogNewMapEvents();
+}
+
+void Deserializer::LogNewMapEvents() {
+  DisallowHeapAllocation no_gc;
+  for (Map map : new_maps()) {
+    DCHECK(FLAG_trace_maps);
+    LOG(isolate_, MapCreate(map));
+    LOG(isolate_, MapDetails(map));
+  }
+}
+
+void Deserializer::LogScriptEvents(Script* script) {
+  DisallowHeapAllocation no_gc;
+  LOG(isolate_,
+      ScriptEvent(Logger::ScriptEventType::kDeserialize, script->id()));
+  LOG(isolate_, ScriptDetails(script));
+}
+
 StringTableInsertionKey::StringTableInsertionKey(String string)
     : StringTableKey(ComputeHashField(string)), string_(string) {
   DCHECK(string->IsInternalizedString());
@@ -203,28 +232,29 @@ HeapObject* Deserializer::PostProcessNewObject(HeapObject* obj, int space) {
       }
     } else if (obj->IsScript()) {
       new_scripts_.push_back(handle(Script::cast(obj), isolate_));
+    } else if (obj->IsAllocationSite()) {
+      // We should link new allocation sites, but we can't do this immediately
+      // because |AllocationSite::HasWeakNext()| internally accesses
+      // |Heap::roots_| that may not have been initialized yet. So defer this to
+      // |ObjectDeserializer::CommitPostProcessedObjects()|.
+      new_allocation_sites_.push_back(AllocationSite::cast(obj));
     } else {
       DCHECK(CanBeDeferred(obj));
     }
-  } else if (obj->IsScript()) {
-    LOG(isolate_, ScriptEvent(Logger::ScriptEventType::kDeserialize,
-                              Script::cast(obj)->id()));
-    LOG(isolate_, ScriptDetails(Script::cast(obj)));
   }
-
-  if (obj->IsAllocationSite()) {
-    // We should link new allocation sites, but we can't do this immediately
-    // because |AllocationSite::HasWeakNext()| internally accesses
-    // |Heap::roots_| that may not have been initialized yet. So defer this to
-    // |ObjectDeserializer::CommitPostProcessedObjects()|.
-    new_allocation_sites_.push_back(AllocationSite::cast(obj));
+  if (obj->IsScript()) {
+    LogScriptEvents(Script::cast(obj));
   } else if (obj->IsCode()) {
-    // We flush all code pages after deserializing the startup snapshot. In that
-    // case, we only need to remember code objects in the large object space.
-    // When deserializing user code, remember each individual code object.
+    // We flush all code pages after deserializing the startup snapshot.
+    // Hence we only remember each individual code object when deserializing
+    // user code.
     if (deserializing_user_code() || space == LO_SPACE) {
       new_code_objects_.push_back(Code::cast(obj));
     }
+  } else if (FLAG_trace_maps && obj->IsMap()) {
+    // Keep track of all seen Maps to log them later since they might be only
+    // partially initialized at this point.
+    new_maps_.push_back(Map::cast(obj));
   } else if (obj->IsAccessorInfo()) {
 #ifdef USE_SIMULATOR
     accessor_infos_.push_back(AccessorInfo::cast(obj));

src/snapshot/deserializer.h

@@ -7,7 +7,9 @@
 
 #include <vector>
 
+#include "src/objects/code.h"
 #include "src/objects/js-array.h"
+#include "src/objects/map.h"
 #include "src/objects/string.h"
 #include "src/snapshot/deserializer-allocator.h"
 #include "src/snapshot/serializer-common.h"
@@ -58,6 +60,11 @@ class Deserializer : public SerializerDeserializer {
   void Initialize(Isolate* isolate);
   void DeserializeDeferredObjects();
 
+  // Create Log events for newly deserialized objects.
+  void LogNewObjectEvents();
+  void LogScriptEvents(Script* script);
+  void LogNewMapEvents();
+
   // This returns the address of an object that has been described in the
   // snapshot by chunk index and offset.
   HeapObject* GetBackReferencedObject(int space);
@@ -76,6 +83,7 @@ class Deserializer : public SerializerDeserializer {
   const std::vector<Code>& new_code_objects() const {
     return new_code_objects_;
   }
+  const std::vector<Map>& new_maps() const { return new_maps_; }
   const std::vector<AccessorInfo*>& accessor_infos() const {
     return accessor_infos_;
   }
@@ -95,6 +103,9 @@ class Deserializer : public SerializerDeserializer {
 
   void Rehash();
 
+  // Cached current isolate.
+  Isolate* isolate_;
+
  private:
   void VisitRootPointers(Root root, const char* description, ObjectSlot start,
                          ObjectSlot end) override;
@@ -130,9 +141,6 @@ class Deserializer : public SerializerDeserializer {
   // Special handling for serialized code like hooking up internalized strings.
   HeapObject* PostProcessNewObject(HeapObject* obj, int space);
 
-  // Cached current isolate.
-  Isolate* isolate_;
-
   // Objects from the attached object descriptions in the serialized user code.
   std::vector<Handle<HeapObject>> attached_objects_;
 
@@ -141,6 +149,7 @@ class Deserializer : public SerializerDeserializer {
 
   ExternalReferenceTable* external_reference_table_;
 
+  std::vector<Map> new_maps_;
   std::vector<AllocationSite*> new_allocation_sites_;
   std::vector<Code> new_code_objects_;
   std::vector<AccessorInfo*> accessor_infos_;

src/snapshot/object-deserializer.cc

@@ -49,7 +49,9 @@ MaybeHandle<HeapObject> ObjectDeserializer::Deserialize(Isolate* isolate) {
     Object* root;
     VisitRootPointer(Root::kPartialSnapshotCache, nullptr, ObjectSlot(&root));
     DeserializeDeferredObjects();
-    FlushICacheForNewCodeObjectsAndRecordEmbeddedObjects();
+    FlushICache();
+    LinkAllocationSites();
+    LogNewMapEvents();
     result = handle(HeapObject::cast(root), isolate);
     Rehash();
     allocator()->RegisterDeserializedObjectsForBlackAllocation();
@@ -58,8 +60,7 @@ MaybeHandle<HeapObject> ObjectDeserializer::Deserialize(Isolate* isolate) {
   return scope.CloseAndEscape(result);
 }
 
-void ObjectDeserializer::
-    FlushICacheForNewCodeObjectsAndRecordEmbeddedObjects() {
+void ObjectDeserializer::FlushICache() {
   DCHECK(deserializing_user_code());
   for (Code code : new_code_objects()) {
     // Record all references to embedded objects in the new code object.
@@ -86,16 +87,18 @@ void ObjectDeserializer::CommitPostProcessedObjects() {
   for (Handle<Script> script : new_scripts()) {
     // Assign a new script id to avoid collision.
     script->set_id(isolate()->heap()->NextScriptId());
-    LOG(isolate(),
-        ScriptEvent(Logger::ScriptEventType::kDeserialize, script->id()));
-    LOG(isolate(), ScriptDetails(*script));
+    LogScriptEvents(*script);
     // Add script to list.
     Handle<WeakArrayList> list = factory->script_list();
     list = WeakArrayList::AddToEnd(isolate(), list,
                                    MaybeObjectHandle::Weak(script));
     heap->SetRootScriptList(*list);
   }
+}
 
+void ObjectDeserializer::LinkAllocationSites() {
+  DisallowHeapAllocation no_gc;
+  Heap* heap = isolate()->heap();
   // Allocation sites are present in the snapshot, and must be linked into
   // a list at deserialization time.
   for (AllocationSite* site : new_allocation_sites()) {

src/snapshot/object-deserializer.h

@@ -25,7 +25,8 @@ class ObjectDeserializer final : public Deserializer {
   // Deserialize an object graph. Fail gracefully.
   MaybeHandle<HeapObject> Deserialize(Isolate* isolate);
 
-  void FlushICacheForNewCodeObjectsAndRecordEmbeddedObjects();
+  void FlushICache();
+  void LinkAllocationSites();
   void CommitPostProcessedObjects();
 };
 

src/snapshot/partial-deserializer.cc

@@ -54,6 +54,7 @@ MaybeHandle<Object> PartialDeserializer::Deserialize(
   CHECK_EQ(start_address, code_space->top());
 
   if (FLAG_rehash_snapshot && can_rehash()) Rehash();
+  LogNewMapEvents();
 
   return Handle<Object>(root, isolate);
 }

src/snapshot/startup-deserializer.cc

@@ -46,7 +46,7 @@ void StartupDeserializer::DeserializeInto(Isolate* isolate) {
 
     // Flush the instruction cache for the entire code-space. Must happen after
     // builtins deserialization.
-    FlushICacheForNewIsolate();
+    FlushICache();
   }
 
   isolate->heap()->set_native_contexts_list(
@@ -58,12 +58,11 @@ void StartupDeserializer::DeserializeInto(Isolate* isolate) {
         ReadOnlyRoots(isolate).undefined_value());
   }
 
-  // Issue code events for newly deserialized code objects.
-  LOG_CODE_EVENT(isolate, LogCodeObjects());
-  LOG_CODE_EVENT(isolate, LogCompiledFunctions());
 
   isolate->builtins()->MarkInitialized();
 
+  LogNewMapEvents();
+
   if (FLAG_rehash_snapshot && can_rehash()) {
     isolate->heap()->InitializeHashSeed();
     read_only_deserializer.RehashHeap();
@@ -71,7 +70,11 @@ void StartupDeserializer::DeserializeInto(Isolate* isolate) {
   }
 }
 
-void StartupDeserializer::FlushICacheForNewIsolate() {
+void StartupDeserializer::LogNewMapEvents() {
+  if (FLAG_trace_maps) LOG(isolate_, LogAllMaps());
+}
+
+void StartupDeserializer::FlushICache() {
   DCHECK(!deserializing_user_code());
   // The entire isolate is newly deserialized. Simply flush all code pages.
   for (Page* p : *isolate()->heap()->code_space()) {

src/snapshot/startup-deserializer.h

@@ -22,7 +22,8 @@ class StartupDeserializer final : public Deserializer {
   void DeserializeInto(Isolate* isolate);
 
  private:
-  void FlushICacheForNewIsolate();
+  void FlushICache();
+  void LogNewMapEvents();
 
   const SnapshotData* read_only_data_;
 };