diff --git a/pkg/compiler/lib/src/js_emitter/startup_emitter/fragment_emitter.dart b/pkg/compiler/lib/src/js_emitter/startup_emitter/fragment_emitter.dart index 539267a397c..93de3899b2f 100644 --- a/pkg/compiler/lib/src/js_emitter/startup_emitter/fragment_emitter.dart +++ b/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 emitEmbeddedGlobalsForDeferredLoading( - DeferredLoadingState deferredLoadingState) { + DeferredLoadingState deferredLoadingState, + {required bool isSplit}) { List 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 globals = []; if (fragmentsToLoad.isNotEmpty) { - globals - .addAll(emitEmbeddedGlobalsForDeferredLoading(deferredLoadingState)); + globals.addAll(emitEmbeddedGlobalsForDeferredLoading(deferredLoadingState, + isSplit: program.isSplit)); } if (program.typeToInterceptorMap != null) { diff --git a/pkg/compiler/lib/src/js_emitter/startup_emitter/model_emitter.dart b/pkg/compiler/lib/src/js_emitter/startup_emitter/model_emitter.dart index f84f7b083ad..73c0d182acd 100644 --- a/pkg/compiler/lib/src/js_emitter/startup_emitter/model_emitter.dart +++ b/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 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 = ; // deferredInitializer[] = 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; } diff --git a/pkg/compiler/test/dump_info/data/deferred/main.dart b/pkg/compiler/test/dump_info/data/deferred/main.dart index 4ce7175ad47..ab1328f2cd8 100644 --- a/pkg/compiler/test/dump_info/data/deferred/main.dart +++ b/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" diff --git a/pkg/compiler/test/dump_info/data/deferred_future/main.dart b/pkg/compiler/test/dump_info/data/deferred_future/main.dart index 01036692f70..959f68b9afb 100644 --- a/pkg/compiler/test/dump_info/data/deferred_future/main.dart +++ b/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" diff --git a/pkg/js_runtime/lib/synced/embedded_names.dart b/pkg/js_runtime/lib/synced/embedded_names.dart index 517c0d3dec7..a82f18370a1 100644 --- a/pkg/js_runtime/lib/synced/embedded_names.dart +++ b/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'; diff --git a/sdk/lib/_internal/js_runtime/lib/js_helper.dart b/sdk/lib/_internal/js_runtime/lib/js_helper.dart index 9f3b92f5373..2d4a370e959 100644 --- a/sdk/lib/_internal/js_runtime/lib/js_helper.dart +++ b/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?> _loadingLibraries = ?>{}; final Set _loadedLibraries = new Set(); -/// Events used to diagnose failures from deferred loading requests. -final List _eventLog = []; - 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 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 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 _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 _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 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); } diff --git a/sdk/lib/_internal/js_runtime/lib/synced/embedded_names.dart b/sdk/lib/_internal/js_runtime/lib/synced/embedded_names.dart index 517c0d3dec7..a82f18370a1 100644 --- a/sdk/lib/_internal/js_runtime/lib/synced/embedded_names.dart +++ b/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';