[test] Extend Memory.json startup snapshot benchmark

Increase the Memory.json run count to 30, add units to deserialization
time traces, and add SharedHeap deserialization timing alongside
per-section serialization timing under --profile-deserialization.

TAG=agy
CONV=accf1fa7-ebf8-4b3c-af8e-b62f22559520

Bug: 573447555
Change-Id: I6980ad1f4340958daf27493eaf5fc60ef3e2713b
Reviewed-on: https://chromium-review.googlesource.com/c/v8/v8/+/8579097
Commit-Queue: Yang Guo <yangguo@chromium.org>
Reviewed-by: Jakob Linke <jgruber@chromium.org>
Cr-Commit-Position: refs/heads/main@{#110686}

src/snapshot/shared-heap-deserializer.cc

@@ -4,6 +4,7 @@
 
 #include "src/snapshot/shared-heap-deserializer.h"
 
+#include "src/base/platform/elapsed-timer.h"
 #include "src/heap/heap-inl.h"
 
 namespace v8 {
@@ -20,6 +21,8 @@ void SharedHeapDeserializer::DeserializeIntoIsolate() {
     return;
   }
 
+  base::ElapsedTimer timer;
+  if (V8_UNLIKELY(v8_flags.profile_deserialization)) timer.Start();
   DCHECK(isolate()->shared_heap_object_cache()->empty());
   HandleScope scope(isolate());
 
@@ -33,6 +36,15 @@ void SharedHeapDeserializer::DeserializeIntoIsolate() {
     // there is no need to call `HashSeed::InitializeRoots(isolate());`.
     Rehash();
   }
+
+  if (V8_UNLIKELY(v8_flags.profile_deserialization)) {
+    // ATTENTION: The Memory.json benchmark greps for this exact output. Do not
+    // change it without also updating Memory.json.
+    const size_t bytes = source()->length();
+    const double ms = timer.Elapsed().InMillisecondsF();
+    PrintF("[Deserializing shared heap (%zu bytes) took %0.3f ms]\n", bytes,
+           ms);
+  }
 }
 
 void SharedHeapDeserializer::DeserializeStringTable() {

src/snapshot/snapshot.cc

@@ -411,41 +411,60 @@ v8::StartupData Snapshot::Create(
   HandleScope scope(isolate);
 
   flags |= Snapshot::kAllowSerializingAllTrustedObjects;
+  const int num_contexts = static_cast<int>(contexts->size());
+  const bool profile = v8_flags.profile_deserialization;
+  base::ElapsedTimer timer;
+  double ro_ms = 0;
+  double startup_ms = 0;
+  double shared_heap_ms = 0;
+  std::vector<double> context_ms(num_contexts, 0.0);
+
+  if (profile) timer.Start();
   ReadOnlySerializer read_only_serializer(isolate, flags);
   read_only_serializer.Serialize();
+  if (profile) ro_ms += timer.Elapsed().InMillisecondsF();
 
   // TODO(v8:6593): generalize rehashing, and remove this flag.
   bool can_be_rehashed = read_only_serializer.can_be_rehashed();
 
   SharedHeapSerializer shared_heap_serializer(isolate, flags);
+  if (profile) timer.Restart();
   StartupSerializer startup_serializer(isolate, flags, &shared_heap_serializer);
   startup_serializer.SerializeStrongReferences(no_gc);
+  if (profile) startup_ms += timer.Elapsed().InMillisecondsF();
 
   // Serialize each context with a new serializer.
-  const int num_contexts = static_cast<int>(contexts->size());
   std::vector<SnapshotData*> context_snapshots;
   context_snapshots.reserve(num_contexts);
 
   std::vector<int> context_allocation_sizes;
   for (int i = 0; i < num_contexts; i++) {
+    if (profile) timer.Restart();
     ContextSerializer context_serializer(isolate, flags, &startup_serializer,
                                          embedder_fields_serializers[i]);
     context_serializer.Serialize(&contexts->at(i), no_gc);
     can_be_rehashed = can_be_rehashed && context_serializer.can_be_rehashed();
     context_snapshots.push_back(new SnapshotData(&context_serializer));
+    if (profile) context_ms[i] = timer.Elapsed().InMillisecondsF();
     if (v8_flags.serialization_statistics) {
       context_allocation_sizes.push_back(
           context_serializer.TotalAllocationSize());
     }
   }
 
+  if (profile) timer.Restart();
   startup_serializer.SerializeWeakReferencesAndDeferred();
   can_be_rehashed = can_be_rehashed && startup_serializer.can_be_rehashed();
 
   startup_serializer.CheckNoDirtyFinalizationRegistries();
+  if (profile) {
+    startup_ms += timer.Elapsed().InMillisecondsF();
+    timer.Restart();
+  }
 
   shared_heap_serializer.FinalizeSerialization();
   can_be_rehashed = can_be_rehashed && shared_heap_serializer.can_be_rehashed();
+  if (profile) shared_heap_ms += timer.Elapsed().InMillisecondsF();
 
   if (v8_flags.serialization_statistics) {
     DCHECK_NE(read_only_serializer.TotalAllocationSize(), 0);
@@ -471,9 +490,31 @@ v8::StartupData Snapshot::Create(
     PrintF("\n");
   }
 
+  if (profile) timer.Restart();
   SnapshotData read_only_snapshot(&read_only_serializer);
+  if (profile) {
+    ro_ms += timer.Elapsed().InMillisecondsF();
+    timer.Restart();
+  }
   SnapshotData shared_heap_snapshot(&shared_heap_serializer);
+  if (profile) {
+    shared_heap_ms += timer.Elapsed().InMillisecondsF();
+    timer.Restart();
+  }
   SnapshotData startup_snapshot(&startup_serializer);
+  if (profile) {
+    startup_ms += timer.Elapsed().InMillisecondsF();
+    PrintF("[Serializing read-only space (%d bytes) took %0.3f ms]\n",
+           read_only_snapshot.RawData().length(), ro_ms);
+    PrintF("[Serializing isolate (%d bytes) took %0.3f ms]\n",
+           startup_snapshot.RawData().length(), startup_ms);
+    PrintF("[Serializing shared heap (%d bytes) took %0.3f ms]\n",
+           shared_heap_snapshot.RawData().length(), shared_heap_ms);
+    for (int i = 0; i < num_contexts; i++) {
+      PrintF("[Serializing context #%d (%d bytes) took %0.3f ms]\n", i,
+             context_snapshots[i]->RawData().length(), context_ms[i]);
+    }
+  }
   v8::StartupData result = SnapshotImpl::CreateSnapshotBlob(
       &startup_snapshot, &read_only_snapshot, &shared_heap_snapshot,
       context_snapshots, can_be_rehashed);

test/memory/Memory.json

@@ -1,7 +1,7 @@
 {
   "owners": ["yangguo@chromium.org", "jgruber@chromium.org"],
   "name": "Memory",
-  "run_count": 5,
+  "run_count": 30,
   "units": "bytes",
   "resources": ["run.js"],
   "main": "run.js",
@@ -39,16 +39,44 @@
     },
     {
       "name": "DeserializationTimeReadOnly",
+      "units": "ms",
       "results_regexp": "\\[Deserializing read-only space \\(\\d+ bytes\\) took ([\\d.]+) ms\\]"
     },
     {
       "name": "DeserializationTimeIsolate",
+      "units": "ms",
       "results_regexp": "\\[Deserializing isolate \\(\\d+ bytes\\) took ([\\d.]+) ms\\]"
     },
+    {
+      "name": "DeserializationTimeSharedHeap",
+      "units": "ms",
+      "results_regexp": "\\[Deserializing shared heap \\(\\d+ bytes\\) took ([\\d.]+) ms\\]"
+    },
     {
       "name": "DeserializationTimeContext",
+      "units": "ms",
       "results_regexp": "\\[Deserializing context #0 \\(\\d+ bytes\\) took ([\\d.]+) ms\\]"
     },
+    {
+      "name": "SerializationTimeReadOnly",
+      "units": "ms",
+      "results_regexp": "\\[Serializing read-only space \\(\\d+ bytes\\) took ([\\d.]+) ms\\]"
+    },
+    {
+      "name": "SerializationTimeStartup",
+      "units": "ms",
+      "results_regexp": "\\[Serializing isolate \\(\\d+ bytes\\) took ([\\d.]+) ms\\]"
+    },
+    {
+      "name": "SerializationTimeSharedHeap",
+      "units": "ms",
+      "results_regexp": "\\[Serializing shared heap \\(\\d+ bytes\\) took ([\\d.]+) ms\\]"
+    },
+    {
+      "name": "SerializationTimeContext",
+      "units": "ms",
+      "results_regexp": "\\[Serializing context #0 \\(\\d+ bytes\\) took ([\\d.]+) ms\\]"
+    },
     {
       "name": "EmbeddedBuiltinsSize",
       "results_regexp": "^Embedded blob is (\\d+) bytes$"