Reland "[log] Properly log all maps creating during bootstrapping"

This is a reland of acfef3ec
Original change's description:
> [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/753885
> Reviewed-by: Yang Guo <yangguo@chromium.org>
> Commit-Queue: Camillo Bruni <cbruni@chromium.org>
> Cr-Commit-Position: refs/heads/master@{#49444}

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

src/bootstrapper.cc

@@ -307,13 +307,18 @@ Handle<Context> Bootstrapper::CreateEnvironment(
     v8::DeserializeEmbedderFieldsCallback embedder_fields_deserializer,
     GlobalContextType context_type) {
   HandleScope scope(isolate_);
+  Handle<Context> env;
+  {
     Genesis genesis(isolate_, maybe_global_proxy, global_proxy_template,
                     context_snapshot_index, embedder_fields_deserializer,
                     context_type);
-  Handle<Context> env = genesis.result();
+    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_);
+  Handle<JSGlobalProxy> global_proxy;
+  {
     Genesis genesis(isolate_, maybe_global_proxy, global_proxy_template);
-  Handle<JSGlobalProxy> global_proxy = genesis.global_proxy();
+    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);
 }
 
@@ -5393,15 +5403,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
@@ -1709,6 +1696,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

@@ -9301,6 +9301,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

@@ -34,6 +34,7 @@
 #include <cmath>
 #endif  // __linux__
 
+#include <unordered_set>
 #include "src/api.h"
 #include "src/log-utils.h"
 #include "src/log.h"
@@ -68,16 +69,16 @@ 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}/.
   while (start < end) {
-    const char* prefixResult = StrNStr(start, prefix, (end - start));
+    const char* prefixResult = strstr(start, prefix);
     if (!prefixResult) return NULL;
     if (suffix == nullptr) return prefixResult;
     const char* suffixResult =
@@ -138,7 +139,7 @@ class ScopedLoggerInitializer {
     printf(
         "======================================================\n"
         "Last log lines:\n...%s\n"
-        "======================================================",
+        "======================================================\n",
         current);
   }
 
@@ -204,6 +205,30 @@ class ScopedLoggerInitializer {
     logger_->StringEvent(name, value);
   }
 
+  void ExtractAllAddresses(std::unordered_set<uintptr_t>* map,
+                           const char* prefix, int field_index) {
+    // Make sure that StopLogging() has been called before.
+    CHECK(log_.size());
+    const char* current = log_.start();
+    while (current != nullptr) {
+      current = FindLine(prefix, nullptr, current);
+      if (current == nullptr) return;
+      // Find token number {index}.
+      const char* previous;
+      for (int i = 0; i <= field_index; i++) {
+        previous = current;
+        current = strchr(current + 1, ',');
+        if (current == nullptr) break;
+        // Skip the comma.
+        current++;
+      }
+      if (current == nullptr) break;
+      uintptr_t address = strtoll(previous, nullptr, 16);
+      CHECK_LT(0, address);
+      map->insert(address);
+    }
+  }
+
  private:
   FILE* StopLoggingGetTempFile() {
     temp_file_ = logger_->TearDown();
@@ -787,6 +812,45 @@ 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();
+    // Extract all the map-detail entry addresses from the log.
+    std::unordered_set<uintptr_t> map_addresses;
+    logger.ExtractAllAddresses(&map_addresses, "map-details", 2);
+    i::Heap* heap = reinterpret_cast<i::Isolate*>(isolate)->heap();
+    i::HeapIterator iterator(heap);
+    i::DisallowHeapAllocation no_gc;
+
+    // Iterate over all maps on the heap.
+    size_t i = 0;
+    for (i::HeapObject* obj = iterator.next(); obj != nullptr;
+         obj = iterator.next()) {
+      i++;
+      if (!obj->IsMap()) continue;
+      uintptr_t address = reinterpret_cast<uintptr_t>(obj);
+      if (map_addresses.find(address) != map_addresses.end()) continue;
+      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, ... %p"
+               "\n# Use logger::PrintLog() for more details.",
+               reinterpret_cast<void*>(obj), i, reinterpret_cast<void*>(obj));
+    }
+    logger.PrintLog(200);
+  }
+  i::FLAG_log_function_events = false;
+  isolate->Dispose();
+}
+
 TEST(ConsoleTimeEvents) {
   SETUP_FLAGS();
   v8::Isolate::CreateParams create_params;