[log] Properly log all maps creating during bootstrapping

Logger::LogMaps will print all maps currently present on the heap.

Note that currently this does not properly log the detailed transitions
for these maps.

Change-Id: Ia3218d371549d7634fe3eda9e8e59b0b0bd8bebb
Reviewed-on: https://chromium-review.googlesource.com/753885Reviewed-by: Yang Guo <yangguo@chromium.org>
Commit-Queue: Camillo Bruni <cbruni@chromium.org>
Cr-Commit-Position: refs/heads/master@{#49444}

src/bootstrapper.cc

@@ -307,13 +307,18 @@ Handle<Context> Bootstrapper::CreateEnvironment(
     v8::DeserializeEmbedderFieldsCallback embedder_fields_deserializer,
     GlobalContextType context_type) {
   HandleScope scope(isolate_);
-  Genesis genesis(isolate_, maybe_global_proxy, global_proxy_template,
-                  context_snapshot_index, embedder_fields_deserializer,
-                  context_type);
-  Handle<Context> env = genesis.result();
-  if (env.is_null() || !InstallExtensions(env, extensions)) {
-    return Handle<Context>();
+  Handle<Context> env;
+  {
+    Genesis genesis(isolate_, maybe_global_proxy, global_proxy_template,
+                    context_snapshot_index, embedder_fields_deserializer,
+                    context_type);
+    env = genesis.result();
+    if (env.is_null() || !InstallExtensions(env, extensions)) {
+      return Handle<Context>();
+    }
   }
+  // Log all maps created during bootstrapping.
+  if (FLAG_trace_maps) LOG(isolate_, LogMaps());
   return scope.CloseAndEscape(env);
 }
 
@@ -321,9 +326,14 @@ Handle<JSGlobalProxy> Bootstrapper::NewRemoteContext(
     MaybeHandle<JSGlobalProxy> maybe_global_proxy,
     v8::Local<v8::ObjectTemplate> global_proxy_template) {
   HandleScope scope(isolate_);
-  Genesis genesis(isolate_, maybe_global_proxy, global_proxy_template);
-  Handle<JSGlobalProxy> global_proxy = genesis.global_proxy();
-  if (global_proxy.is_null()) return Handle<JSGlobalProxy>();
+  Handle<JSGlobalProxy> global_proxy;
+  {
+    Genesis genesis(isolate_, maybe_global_proxy, global_proxy_template);
+    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());
   return scope.CloseAndEscape(global_proxy);
 }
 
@@ -5388,15 +5398,6 @@ Genesis::Genesis(
     AddToWeakNativeContextList(*native_context());
     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();
-      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) {
       Handle<JSGlobalObject> global_object =

src/log.cc

@@ -1381,26 +1381,10 @@ 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;
@@ -1430,6 +1414,9 @@ void Logger::MapEvent(const char* type, Map* from, Map* to, const char* reason,
 
 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
@@ -1705,6 +1692,16 @@ void Logger::LogAccessorCallbacks() {
   }
 }
 
+void Logger::LogMaps() {
+  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));
+  }
+}
 
 static void AddIsolateIdIfNeeded(std::ostream& os,  // NOLINT
                                  Isolate* isolate) {

src/log.h

@@ -202,7 +202,6 @@ 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);
@@ -259,6 +258,8 @@ class Logger : public CodeEventListener {
   void LogCodeObjects();
   // Used for logging bytecode handlers found in the snapshot.
   void LogBytecodeHandlers();
+  // Logs all Mpas foind in the heap.
+  void LogMaps();
 
   // Converts tag to a corresponding NATIVE_... if the script is native.
   INLINE(static CodeEventListener::LogEventsAndTags ToNativeByScript(

src/objects.cc

@@ -9294,6 +9294,11 @@ void Map::ConnectTransition(Handle<Map> parent, Handle<Map> child,
   // Do not track transitions during bootstrap except for element transitions.
   if (isolate->bootstrapper()->IsActive() &&
       !name.is_identical_to(isolate->factory()->elements_transition_symbol())) {
+    if (FLAG_trace_maps) {
+      LOG(isolate,
+          MapEvent("Transition", *parent, *child,
+                   child->is_prototype_map() ? "prototype" : "", *name));
+    }
     return;
   }
   if (!parent->GetBackPointer()->IsUndefined(isolate)) {

test/cctest/test-log.cc

@@ -68,11 +68,11 @@ static const char* StrNStr(const char* s1, const char* s2, size_t n) {
   return strstr(s1, s2);
 }
 
+// Look for a log line which starts with {prefix} and ends with {suffix}.
 static const char* FindLogLine(const char* start, const char* end,
                                const char* prefix,
                                const char* suffix = nullptr) {
   CHECK_LT(start, end);
-  // Look for a log line which starts with {prefix} and ends with {suffix}.
   CHECK_EQ(end[0], '\0');
   size_t prefixLength = strlen(prefix);
   // Loop through the input until we find /{prefix}[^\n]+{suffix}/.
@@ -787,6 +787,47 @@ TEST(TraceMaps) {
   isolate->Dispose();
 }
 
+TEST(LogMaps) {
+  // Test that all Map details from Maps in the snapshot are logged properly.
+  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);
+    logger.StopLogging();
+    i::Heap* heap = reinterpret_cast<i::Isolate*>(isolate)->heap();
+    i::HeapIterator iterator(heap);
+    i::DisallowHeapAllocation no_gc;
+    const size_t kBufferSize = 512;
+    char log_line_suffix[kBufferSize] = {0};
+    // Iterate over all maps on the heap.
+    size_t i = 0;
+    for (i::HeapObject* obj = iterator.next(); obj != nullptr;
+         obj = iterator.next()) {
+      if (!obj->IsMap()) continue;
+      // Look for the "map-details" in the log for the given Map's address.
+      v8::base::OS::SNPrintF(log_line_suffix, kBufferSize, ",0x%" V8PRIxPTR ",",
+                             reinterpret_cast<intptr_t>(obj));
+      const char* pos = logger.FindLine("map-details,", log_line_suffix);
+      if (pos == nullptr) {
+        logger.PrintLog(200);
+        i::Map::cast(obj)->Print();
+        V8_Fatal(
+            __FILE__, __LINE__,
+            "Map (%p, #%zu) was not logged during startup with --trace-maps!"
+            "\n# Expected Log Line: map_details, ... %s"
+            "\n# Use logger::PrintLog() for more details.",
+            reinterpret_cast<void*>(obj), i, log_line_suffix);
+      }
+    }
+    i++;
+  }
+  i::FLAG_log_function_events = false;
+  isolate->Dispose();
+}
+
 TEST(ConsoleTimeEvents) {
   SETUP_FLAGS();
   v8::Isolate::CreateParams create_params;