[VM/Service] Record timeline events representing completed microtasks

TEST=pkg/vm_service/test/timeline_events_for_completed_microtasks_test

CoreLibraryReviewExempt: This CL does not include any core library API
changes, it only modifies the implementation of microtasks (by
instrumenting them).
Change-Id: I54d886db9519c73f9e3218a9cc1c46bc9fe9acc3
Reviewed-on: https://dart-review.googlesource.com/c/sdk/+/420221
Commit-Queue: Derek Xu <[email protected]>
Reviewed-by: Ben Konyi <[email protected]>

Author: derekxu16

pkg/vm_service/test/common/service_test_common.dart

@@ -5,11 +5,13 @@
 library service_test_common;
 
 import 'dart:async';
+import 'dart:collection' show HashMap;
 import 'dart:typed_data';
 
 import 'package:path/path.dart' as p;
 import 'package:test/test.dart';
 import 'package:vm_service/vm_service.dart';
+import 'package:vm_service_protos/vm_service_protos.dart' show DebugAnnotation;
 
 typedef IsolateTest = Future<void> Function(
   VmService service,
@@ -914,3 +916,19 @@ IsolateTest testExpressionEvaluationAndAvailableVariables(
     }
   };
 }
+
+Map<String, String> mapFromListOfDebugAnnotations(
+  List<DebugAnnotation> debugAnnotations,
+) {
+  return HashMap.fromEntries(
+    debugAnnotations.map((a) {
+      if (a.hasStringValue()) {
+        return MapEntry(a.name, a.stringValue);
+      } else if (a.hasLegacyJsonValue()) {
+        return MapEntry(a.name, a.legacyJsonValue);
+      } else {
+        throw 'We should not be writing annotations without values';
+      }
+    }),
+  );
+}

pkg/vm_service/test/get_perfetto_vm_timeline_rpc_test.dart

@@ -5,7 +5,6 @@
 // VMOptions=
 // VMOptions=--intern_strings_when_writing_perfetto_timeline
 
-import 'dart:collection';
 import 'dart:convert';
 import 'dart:developer';
 import 'dart:io' show Platform;
@@ -14,6 +13,7 @@ import 'package:test/test.dart';
 import 'package:vm_service/vm_service.dart' hide Timeline;
 import 'package:vm_service_protos/vm_service_protos.dart';
 
+import 'common/service_test_common.dart' show mapFromListOfDebugAnnotations;
 import 'common/test_helper.dart';
 
 void primeTimeline() {
@@ -143,22 +143,6 @@ List<TrackEvent> extractTrackEventsFromTracePackets(
   return result;
 }
 
-Map<String, String> mapFromListOfDebugAnnotations(
-  List<DebugAnnotation> debugAnnotations,
-) {
-  return HashMap.fromEntries(
-    debugAnnotations.map((a) {
-      if (a.hasStringValue()) {
-        return MapEntry(a.name, a.stringValue);
-      } else if (a.hasLegacyJsonValue()) {
-        return MapEntry(a.name, a.legacyJsonValue);
-      } else {
-        throw 'We should not be writing annotations without values';
-      }
-    }),
-  );
-}
-
 void checkThatAllEventsHaveIsolateNumbers(Iterable<TrackEvent> events) {
   for (final event in events) {
     final debugAnnotations =

pkg/vm_service/test/timeline_events_for_completed_microtasks_test.dart

@@ -0,0 +1,64 @@
+// Copyright (c) 2025, the Dart project authors.  Please see the AUTHORS file
+// for details. All rights reserved. Use of this source code is governed by a
+// BSD-style license that can be found in the LICENSE file.
+
+import 'dart:async';
+import 'dart:convert';
+
+import 'package:test/test.dart';
+import 'package:vm_service/vm_service.dart' hide Timeline;
+import 'package:vm_service_protos/vm_service_protos.dart';
+
+import 'common/service_test_common.dart' show mapFromListOfDebugAnnotations;
+import 'common/test_helper.dart';
+
+const String shortFile = 'timeline_events_for_completed_microtasks_test.dart';
+
+void primeTimeline() {
+  for (int i = 0; i < 5; i++) {
+    scheduleMicrotask(() {});
+  }
+}
+
+Iterable<TrackEvent> extractTrackEventsFromTracePackets(
+  List<TracePacket> packets,
+) =>
+    packets
+        .where((packet) => packet.hasTrackEvent())
+        .map((packet) => packet.trackEvent);
+
+final tests = <IsolateTest>[
+  (VmService service, IsolateRef isolateRef) async {
+    final result = await service.getPerfettoVMTimeline();
+
+    final trace = Trace.fromBuffer(base64Decode(result.trace!));
+    final packets = trace.packet;
+    final mainIsolateMicrotaskEvents =
+        extractTrackEventsFromTracePackets(packets)
+            .where((event) => event.name == 'Microtask')
+            .where((event) {
+      final debugAnnotations =
+          mapFromListOfDebugAnnotations(event.debugAnnotations);
+      return debugAnnotations['isolateId'] == isolateRef.id;
+    });
+    expect(mainIsolateMicrotaskEvents.length, greaterThanOrEqualTo(5));
+
+    for (final event in mainIsolateMicrotaskEvents) {
+      final debugAnnotations =
+          mapFromListOfDebugAnnotations(event.debugAnnotations);
+      expect(debugAnnotations['microtaskId'], isNotNull);
+      expect(
+        debugAnnotations['stack trace captured when microtask was enqueued'],
+        contains(shortFile),
+      );
+    }
+  },
+];
+
+void main([args = const <String>[]]) => runIsolateTests(
+      args,
+      tests,
+      shortFile,
+      testeeBefore: primeTimeline,
+      extraArgs: ['--profile-microtasks', '--timeline-streams=Microtask'],
+    );

runtime/lib/async.cc

@@ -5,12 +5,17 @@
 #include "vm/bootstrap_natives.h"
 #include "vm/debugger.h"
 #include "vm/exceptions.h"
+#include "vm/flags.h"
+#include "vm/microtask_mirror_queues.h"
 #include "vm/native_entry.h"
 #include "vm/object_store.h"
 #include "vm/runtime_entry.h"
 
 namespace dart {
 
+// This flag is defined in "vm/microtask_mirror_queues.cc".
+DECLARE_FLAG(bool, profile_microtasks);
+
 DEFINE_NATIVE_ENTRY(AsyncStarMoveNext_debuggerStepCheck, 0, 1) {
 #if !defined(PRODUCT)
   GET_NON_NULL_NATIVE_ARGUMENT(Closure, generator, arguments->NativeArgAt(0));
@@ -56,4 +61,41 @@ DEFINE_NATIVE_ENTRY(SuspendState_instantiateClosureWithFutureTypeArgument,
   return closure.ptr();
 }
 
+DEFINE_NATIVE_ENTRY(MicrotaskMirrorQueue_onScheduleAsyncCallback, 0, 1) {
+#if !defined(PRODUCT)
+  if (FLAG_profile_microtasks) {
+    GET_NON_NULL_NATIVE_ARGUMENT(StackTrace, stack_trace,
+                                 arguments->NativeArgAt(0));
+    MicrotaskMirrorQueues::GetQueue(static_cast<int64_t>(isolate->main_port()))
+        ->OnScheduleAsyncCallback(stack_trace);
+  }
+#endif  // !defined(PRODUCT)
+  return Object::null();
+}
+
+DEFINE_NATIVE_ENTRY(MicrotaskMirrorQueue_onSchedulePriorityAsyncCallback,
+                    0,
+                    0) {
+#if !defined(PRODUCT)
+  if (FLAG_profile_microtasks) {
+    MicrotaskMirrorQueues::GetQueue(static_cast<int64_t>(isolate->main_port()))
+        ->OnSchedulePriorityAsyncCallback();
+  }
+#endif  // !defined(PRODUCT)
+  return Object::null();
+}
+
+DEFINE_NATIVE_ENTRY(MicrotaskMirrorQueue_onAsyncCallbackComplete, 0, 2) {
+#if !defined(PRODUCT)
+  if (FLAG_profile_microtasks) {
+    GET_NON_NULL_NATIVE_ARGUMENT(Integer, start_time,
+                                 arguments->NativeArgAt(0));
+    GET_NON_NULL_NATIVE_ARGUMENT(Integer, end_time, arguments->NativeArgAt(1));
+    MicrotaskMirrorQueues::GetQueue(static_cast<int64_t>(isolate->main_port()))
+        ->OnAsyncCallbackComplete(start_time.Value(), end_time.Value());
+  }
+#endif  // !defined(PRODUCT)
+  return Object::null();
+}
+
 }  // namespace dart

runtime/vm/bootstrap_natives.h

@@ -149,6 +149,9 @@ namespace dart {
   V(Timeline_getTraceClock, 0)                                                 \
   V(Timeline_isDartStreamEnabled, 0)                                           \
   V(Timeline_reportTaskEvent, 5)                                               \
+  V(MicrotaskMirrorQueue_onScheduleAsyncCallback, 1)                           \
+  V(MicrotaskMirrorQueue_onSchedulePriorityAsyncCallback, 0)                   \
+  V(MicrotaskMirrorQueue_onAsyncCallbackComplete, 2)                           \
   V(TypedDataBase_length, 1)                                                   \
   V(TypedDataBase_setClampedRange, 5)                                          \
   V(TypedData_GetFloat32, 2)                                                   \

runtime/vm/dart.cc

@@ -33,6 +33,7 @@
 #include "vm/kernel_isolate.h"
 #include "vm/message_handler.h"
 #include "vm/metrics.h"
+#include "vm/microtask_mirror_queues.h"
 #include "vm/native_entry.h"
 #include "vm/native_message_handler.h"
 #include "vm/object.h"
@@ -764,6 +765,7 @@ char* Dart::Cleanup() {
   }
   Timeline::Cleanup();
 #endif
+  NOT_IN_PRODUCT(MicrotaskMirrorQueues::CleanUp());
   Zone::Cleanup();
   Random::Cleanup();
   // Delete the current thread's TLS and set it's TLS to null.

runtime/vm/microtask_mirror_queues.cc

@@ -0,0 +1,99 @@
+// Copyright (c) 2025, the Dart project authors.  Please see the AUTHORS file
+// for details. All rights reserved. Use of this source code is governed by a
+// BSD-style license that can be found in the LICENSE file.
+
+#if !defined(PRODUCT)
+
+#include "vm/microtask_mirror_queues.h"
+
+#include <utility>
+
+#include "platform/hashmap.h"
+#include "vm/flags.h"
+#include "vm/object.h"
+#include "vm/timeline.h"
+
+namespace dart {
+
+DEFINE_FLAG(
+    bool,
+    profile_microtasks,
+    false,
+    "Record information about each microtask. Information about completed "
+    "microtasks will be written to the \"Microtask\" timeline stream.");
+
+MicrotaskMirrorQueue* MicrotaskMirrorQueues::GetQueue(int64_t isolate_id) {
+  void* key = reinterpret_cast<void*>(isolate_id);
+  const intptr_t hash = Utils::WordHash(isolate_id);
+
+  MutexLocker ml(&isolate_id_to_queue_lock_);
+
+  SimpleHashMap::Entry* entry = isolate_id_to_queue_.Lookup(key, hash, true);
+  if (entry->value == nullptr) {
+    entry->value = new MicrotaskMirrorQueue();
+  }
+  return static_cast<MicrotaskMirrorQueue*>(entry->value);
+}
+
+void MicrotaskMirrorQueue::OnScheduleAsyncCallback(const StackTrace& st) {
+  if (is_disabled_) {
+    return;
+  }
+
+  queue_.PushBack(MicrotaskMirrorQueueEntry(
+      next_available_id_++, CStringUniquePtr(Utils::StrDup(st.ToCString()))));
+}
+
+void MicrotaskMirrorQueue::OnSchedulePriorityAsyncCallback() {
+  // If this function is called, it means that the microtask queue can no longer
+  // be accurately modeled by a |ListQueue|. This only ever gets called when an
+  // exception goes unhandled, so we just handle the situation by disabling all
+  // further reads from / writes to this queue.
+  is_disabled_ = true;
+}
+
+void MicrotaskMirrorQueue::OnAsyncCallbackComplete(int64_t start_time,
+                                                   int64_t end_time) {
+  if (is_disabled_) {
+    return;
+  }
+
+  ASSERT(queue_.Length() >= 1);
+  MicrotaskMirrorQueueEntry&& front = std::move(queue_.PopFront());
+
+  TimelineStream* stream = Timeline::GetMicrotaskStream();
+  ASSERT(stream != nullptr);
+  TimelineEvent* event = stream->StartEvent();
+  if (event != nullptr) {
+    if (start_time < end_time) {
+      event->Duration("Microtask", start_time, end_time);
+    } else {
+      event->Instant("Microtask", start_time);
+    }
+
+    event->SetNumArguments(2);
+    event->FormatArgument(0, "microtaskId", "%" Pd, front.id());
+    event->SetArgument(1, "stack trace captured when microtask was enqueued",
+                       front.ReleaseStackTrace());
+    event->Complete();
+  }
+}
+
+Mutex MicrotaskMirrorQueues::isolate_id_to_queue_lock_;
+
+SimpleHashMap MicrotaskMirrorQueues::isolate_id_to_queue_(
+    &SimpleHashMap::SamePointerValue,
+    MicrotaskMirrorQueues::kIsolateIdToQueueInitialCapacity);
+
+void MicrotaskMirrorQueues::CleanUp() {
+  for (SimpleHashMap::Entry* entry = isolate_id_to_queue_.Start();
+       entry != nullptr; entry = isolate_id_to_queue_.Next(entry)) {
+    MicrotaskMirrorQueue* value =
+        static_cast<MicrotaskMirrorQueue*>(entry->value);
+    delete value;
+  }
+}
+
+}  // namespace dart
+
+#endif  // !defined(PRODUCT)