[dart2js] Improve deferred part file logging.

Adds an "eventLog" property to the global "$__dart_deferred_initializers__" object. The event log is just a JS Array that gets initialized alongside $__dart_deferred_initializers__.

Each event entry is a String->String JS object. I unified the format of these event objects for easier parsing.

Each printed event is now valid JSON (passed through JSON.stringify) so we can more easily post-process the logs if necessary.

Fully replacing the existing "_eventLog" field makes the logging logic simpler. Having a single array allows us to not include a timestamp because the array captures the event ordering (actual timing doesn't matter). It also makes it easier to stringify the logs when there's only 1 data source/format.

Sample output:
```

{"hunkName":"out.js_1.part.js","event":"loadHunk"}
{"uri":"path_to/out.js_1.part.js","hunkName":"out.js_1.part.js","event":"downloadHunk"}
{"file":"out.js_1","event":"beginLoadPart"}
{"file":"out.js_1","event":"endPartLoad","hash":"aCscY7yv4EHodRPmCqYn5BqMelA="}
{"uri":"path_to/out.js_1.part.js","hunkName":"out.js_1.part.js","event":"downloadHunkSuccess"}
{"hunkName":"out.js_1.part.js","hash":"aCscY7yv4EHodRPmCqYn5BqMelA=","event":"initialize"}

```

Change-Id: Ifee73be0bf7dc53a0e7710ff033dd2b0fae9fb0e
Reviewed-on: https://dart-review.googlesource.com/c/sdk/+/307240
Commit-Queue: Nate Biggs <natebiggs@google.com>
Reviewed-by: Stephen Adams <sra@google.com>

pkg/compiler/lib/src/js_emitter/startup_emitter/fragment_emitter.dart

@@ -1691,7 +1691,8 @@ class FragmentEmitter {
   /// to the list of generated fragments that must be installed when the
   /// deferred library is loaded.
   Iterable<js.Property> emitEmbeddedGlobalsForDeferredLoading(
-      DeferredLoadingState deferredLoadingState) {
+      DeferredLoadingState deferredLoadingState,
+      {required bool isSplit}) {
     List<js.Property> globals = [];
 
     globals.add(js.Property(
@@ -1723,6 +1724,11 @@ class FragmentEmitter {
       'deferredInitialized': generateEmbeddedGlobalAccess(DEFERRED_INITIALIZED)
     });
 
+    if (isSplit) {
+      js.Expression eventLog = js.js("$deferredGlobal.eventLog");
+      globals.add(js.Property(js.string(INITIALIZATION_EVENT_LOG), eventLog));
+    }
+
     globals.add(js.Property(
         js.string(INITIALIZE_LOADED_HUNK), initializeLoadedHunkFunction));
 
@@ -1842,8 +1848,8 @@ class FragmentEmitter {
     List<js.Property> globals = [];
 
     if (fragmentsToLoad.isNotEmpty) {
-      globals
-          .addAll(emitEmbeddedGlobalsForDeferredLoading(deferredLoadingState));
+      globals.addAll(emitEmbeddedGlobalsForDeferredLoading(deferredLoadingState,
+          isSplit: program.isSplit));
     }
 
     if (program.typeToInterceptorMap != null) {

pkg/compiler/lib/src/js_emitter/startup_emitter/model_emitter.dart

@@ -12,6 +12,7 @@ import 'package:js_runtime/synced/embedded_names.dart'
         DEFERRED_LIBRARY_PARTS,
         DEFERRED_PART_URIS,
         DEFERRED_PART_HASHES,
+        INITIALIZATION_EVENT_LOG,
         INITIALIZE_LOADED_HUNK,
         INTERCEPTORS_BY_TAG,
         IS_HUNK_INITIALIZED,
@@ -342,8 +343,7 @@ class ModelEmitter {
 
     _task.measureSubtask('write fragments', () {
       writeMainFragment(mainFragment, mainCode,
-          isSplit: program.deferredFragments.isNotEmpty ||
-              _options.experimentalTrackAllocations);
+          isSplit: program.isSplit || _options.experimentalTrackAllocations);
     });
 
     if (_closedWorld.backendUsage.requiresPreamble &&
@@ -377,11 +377,20 @@ class ModelEmitter {
     return js.Comment(generatedBy(_options, flavor: '$flavor'));
   }
 
-  js.Statement buildDeferredInitializerGlobal() {
-    return js.js.statement(
-        'self.#deferredInitializers = '
-        'self.#deferredInitializers || Object.create(null);',
-        {'deferredInitializers': deferredInitializersGlobal});
+  List<js.Statement> buildDeferredInitializerGlobal() {
+    return [
+      js.js.statement(
+          'self.#deferredInitializers = '
+          'self.#deferredInitializers || Object.create(null);',
+          {'deferredInitializers': deferredInitializersGlobal}),
+      js.js.statement(
+          'self.#deferredInitializers.#eventLog = '
+          'self.#deferredInitializers.#eventLog || [];',
+          {
+            'deferredInitializers': deferredInitializersGlobal,
+            'eventLog': INITIALIZATION_EVENT_LOG
+          })
+    ];
   }
 
   js.Statement buildStartupMetrics() {
@@ -432,7 +441,7 @@ var ${startupMetricsGlobal} =
     js.Program program = js.Program([
       buildGeneratedBy(),
       js.Comment(HOOKS_API_USAGE),
-      if (isSplit) buildDeferredInitializerGlobal(),
+      if (isSplit) ...buildDeferredInitializerGlobal(),
       if (_closedWorld.backendUsage.requiresStartupMetrics)
         buildStartupMetrics(),
       code
@@ -571,10 +580,20 @@ var ${startupMetricsGlobal} =
     //   deferredInitializer.current = <pretty-printed code>;
     //   deferredInitializer[<hash>] = deferredInitializer.current;
 
+    final outputFileJsString = js.string(outputFileName);
     js.Program program = js.Program([
       if (isFirst) buildGeneratedBy(),
-      if (isFirst) buildDeferredInitializerGlobal(),
-      js.js.statement('$deferredInitializersGlobal.current = #', code)
+      if (isFirst) ...buildDeferredInitializerGlobal(),
+      js.js.statement(
+          '#deferredInitializers.#eventLog.push({"part": '
+          '#outputFileName, "event": "beginLoadPart"});',
+          {
+            'deferredInitializers': deferredInitializersGlobal,
+            'eventLog': INITIALIZATION_EVENT_LOG,
+            'outputFileName': outputFileJsString
+          }),
+      js.js.statement('#deferredInitializers.current = #code',
+          {'deferredInitializers': deferredInitializersGlobal, 'code': code})
     ]);
 
     Hasher hasher = Hasher();
@@ -591,10 +610,30 @@ var ${startupMetricsGlobal} =
     // This will be used to retrieve the initializing function from the global
     // variable.
     String hash = hasher.getHash();
+    final jsStringHash = js.string(hash);
 
     // Now we copy the deferredInitializer.current into its correct hash.
-    output.add('\n${deferredInitializersGlobal}["$hash"] = '
-        '${deferredInitializersGlobal}.current\n');
+    final epilogue = js.Program([
+      js.js.statement(
+          '#deferredInitializers[#hash] = #deferredInitializers.current', {
+        'deferredInitializers': deferredInitializersGlobal,
+        'hash': jsStringHash
+      }),
+      js.js.statement(
+          '#deferredInitializers.#eventLog.push({"part": #outputFileName, '
+          '"hash": #hash, "event": "endPartLoad"})',
+          {
+            'deferredInitializers': deferredInitializersGlobal,
+            'hash': jsStringHash,
+            'eventLog': INITIALIZATION_EVENT_LOG,
+            'outputFileName': outputFileJsString,
+          })
+    ]);
+    output.add('\n');
+    output.add(js
+        .createCodeBuffer(epilogue, _options,
+            _sourceInformationStrategy as JavaScriptSourceInformationStrategy)
+        .getText());
     return hash;
   }
 

pkg/compiler/test/dump_info/data/deferred/main.dart

@@ -104,7 +104,7 @@
   "id": "outputUnit/1",
   "kind": "outputUnit",
   "name": "1",
-  "size": 1112,
+  "size": 1426,
   "filename": "out_1.part.js",
   "imports": [
     "lib"

pkg/compiler/test/dump_info/data/deferred_future/main.dart

@@ -110,7 +110,7 @@
   "id": "outputUnit/1",
   "kind": "outputUnit",
   "name": "1",
-  "size": 834,
+  "size": 1148,
   "filename": "out_1.part.js",
   "imports": [
     "lib1"

pkg/js_runtime/lib/synced/embedded_names.dart

@@ -159,6 +159,16 @@ const IS_HUNK_INITIALIZED = 'isHunkInitialized';
 /// globals don't clash with it.
 const DEFERRED_INITIALIZED = 'deferredInitialized';
 
+/// Property name for the reference to the initialization event log which is
+/// included in exceptions when deferred loading fails.
+///
+/// The event log is a JS array where each entry is a plain JS object
+/// representing event data. Each entry will be passed to JSON.stringify()
+/// before being appended to the thrown exception.
+///
+/// This embedded global is only used for deferred loading.
+const INITIALIZATION_EVENT_LOG = 'eventLog';
+
 /// An embedded global used to collect and access runtime metrics.
 const RUNTIME_METRICS = 'rm';
 

sdk/lib/_internal/js_runtime/lib/js_helper.dart

@@ -11,6 +11,7 @@ import 'dart:_js_embedded_names'
         DEFERRED_PART_URIS,
         DEFERRED_PART_HASHES,
         GET_ISOLATE_TAG,
+        INITIALIZATION_EVENT_LOG,
         INITIALIZE_LOADED_HUNK,
         INTERCEPTORS_BY_TAG,
         IS_HUNK_LOADED,
@@ -2758,14 +2759,39 @@ String getIsolateAffinityTag(String name) {
 final Map<String, Future<Null>?> _loadingLibraries = <String, Future<Null>?>{};
 final Set<String> _loadedLibraries = new Set<String>();
 
-/// Events used to diagnose failures from deferred loading requests.
-final List<String> _eventLog = <String>[];
-
 typedef void DeferredLoadCallback();
 
 // Function that will be called every time a new deferred import is loaded.
 DeferredLoadCallback? deferredLoadHook;
 
+/// Add events to global initialization event log.
+void _addEvent(Map<String, String> data) {
+  var initializationEventLog = JS_EMBEDDED_GLOBAL('', INITIALIZATION_EVENT_LOG);
+  var dataObj = JS('=Object', 'Object.create(null)');
+  data.forEach((key, value) {
+    JS('', '#[#] = #', dataObj, key, value);
+  });
+  JS('', '#.push(#)', initializationEventLog, dataObj);
+}
+
+/// Returns the event log as a string where each line is a JSON format event.
+///
+/// The events are printed in reverse chronological order in case the tail gets
+/// truncated, the newest events are retained.
+String _getEventLog() {
+  var initializationEventLog = JS_EMBEDDED_GLOBAL('', INITIALIZATION_EVENT_LOG);
+  final log = JS(
+      'String',
+      'Array.from(#)'
+          '.map(((script) => '
+          '(e, i) => { e["index"] = i; e["script"] = script; return e; })(#))'
+          '.reverse()'
+          '.map((e) => JSON.stringify(e)).join("\\n")',
+      initializationEventLog,
+      thisScript);
+  return log;
+}
+
 /// Loads a deferred library. The compiler generates a call to this method to
 /// implement `import.loadLibrary()`. The [priority] argument is the index of
 /// one of the [LoadLibraryPriority] enum's members.
@@ -2820,19 +2846,21 @@ Future<Null> loadDeferredLibrary(String loadId, int priority) {
       var uri = uris[i];
       var hash = hashes[i];
       if (JS('bool', '#(#)', isHunkInitialized, hash)) {
-        _eventLog.add(' - already initialized: $uri ($hash)');
+        _addEvent(
+            {'part': '$uri', 'hash': '$hash', 'event': 'alreadyInitialized'});
         continue;
       }
       // On strange scenarios, e.g. if js encounters parse errors, we might get
       // an "success" callback on the script load but the hunk will be null.
       if (JS('bool', '#(#)', isHunkLoaded, hash)) {
-        _eventLog.add(' - initialize: $uri ($hash)');
+        _addEvent({'part': '$uri', 'hash': '$hash', 'event': 'initialize'});
         JS('void', '#(#)', initializer, hash);
       } else {
-        _eventLog.add(' - missing hunk: $uri ($hash)');
+        _addEvent({'part': '$uri', 'hash': '$hash', 'event': 'missing'});
+
         throw new DeferredLoadException("Loading ${uris[i]} failed: "
             "the code with hash '${hash}' was not loaded.\n"
-            "event log:\n${_eventLog.join("\n")}\n");
+            "event log:\n${_getEventLog()}\n");
       }
     }
   }
@@ -2999,10 +3027,12 @@ String _computeThisScriptFromTrace() {
 }
 
 Future<Null> _loadHunk(String hunkName, String loadId, int priority) {
+  var initializationEventLog = JS_EMBEDDED_GLOBAL('', INITIALIZATION_EVENT_LOG);
+
   var future = _loadingLibraries[hunkName];
-  _eventLog.add(' - _loadHunk: $hunkName');
+  _addEvent({'part': hunkName, 'event': 'startLoad'});
   if (future != null) {
-    _eventLog.add('reuse: $hunkName');
+    _addEvent({'part': hunkName, 'event': 'reuse'});
     return future.then((Null _) => null);
   }
 
@@ -3012,23 +3042,24 @@ Future<Null> _loadHunk(String hunkName, String loadId, int priority) {
   // sanitized URL.
   String uriAsString = JS('', '#.toString()', trustedScriptUri);
 
-  _eventLog.add(' - download: $hunkName from $uriAsString');
+  _addEvent({'uri': uriAsString, 'part': hunkName, 'event': 'download'});
 
   var deferredLibraryLoader = JS('', 'self.dartDeferredLibraryLoader');
   Completer<Null> completer = Completer();
 
   void success() {
-    _eventLog.add(' - download success: $hunkName');
+    _addEvent({'part': hunkName, 'event': 'downloadSuccess'});
     completer.complete(null);
   }
 
   void failure(error, String context, StackTrace? stackTrace) {
-    _eventLog.add(' - download failed: $hunkName (context: $context)');
+    _addEvent(
+        {'part': hunkName, 'context': context, 'event': 'downloadFailure'});
     _loadingLibraries[hunkName] = null;
     stackTrace ??= StackTrace.current;
     completer.completeError(
         DeferredLoadException('Loading $uriAsString failed: $error\n'
-            'event log:\n${_eventLog.join("\n")}\n'),
+            'event log:\n${_getEventLog()}\n'),
         stackTrace);
   }
 

sdk/lib/_internal/js_runtime/lib/synced/embedded_names.dart

@@ -159,6 +159,16 @@ const IS_HUNK_INITIALIZED = 'isHunkInitialized';
 /// globals don't clash with it.
 const DEFERRED_INITIALIZED = 'deferredInitialized';
 
+/// Property name for the reference to the initialization event log which is
+/// included in exceptions when deferred loading fails.
+///
+/// The event log is a JS array where each entry is a plain JS object
+/// representing event data. Each entry will be passed to JSON.stringify()
+/// before being appended to the thrown exception.
+///
+/// This embedded global is only used for deferred loading.
+const INITIALIZATION_EVENT_LOG = 'eventLog';
+
 /// An embedded global used to collect and access runtime metrics.
 const RUNTIME_METRICS = 'rm';