[VM] Add automatic detection of timers that are significantly overdue

This change makes it so that when the VM detects that a timer is at
least 100 ms overdue, it sends a warning in a VM Service event on the
'Timer' stream.

TEST=Built an Android Flutter app with a modified Engine that contained
a `sleep` call in `eventhandler_linux.cc` and confirmed that the warning
event got sent, built an iOS Flutter app with a modified Engine that
contained a `sleep` call in `eventhandler_macos.cc` and verified that
the warning event got sent,
pkg/vm_service/test/overdue_timer_detection_test

CoreLibraryReviewExempt: This CL does not include any core library API
changes, only VM Service implementation changes.
Change-Id: Ie8db047116b7f63cfb5413f763eaf56c7bdd6975
Reviewed-on: https://dart-review.googlesource.com/c/sdk/+/409500
Reviewed-by: Ben Konyi <[email protected]>
Commit-Queue: Derek Xu <[email protected]>

Author: derekxu16

pkg/vm_service/CHANGELOG.md

@@ -1,3 +1,9 @@
+## 15.0.1
+- Update to version `4.17` of the spec.
+- Add `Timer` stream.
+- Add `TimerSignificantlyOverdue` event kind.
+- Add `details` property to `Event`.
+
 ## 15.0.0
 - Update type of `CodeRef.function` from `FuncRef` to `dynamic` to allow for `NativeFunction`
   functions ([flutter/devtools #8567]).

pkg/vm_service/java/version.properties

@@ -1 +1 @@
-version=4.16
+version=4.17

pkg/vm_service/lib/src/vm_service.dart

@@ -27,7 +27,7 @@ export 'snapshot_graph.dart'
         HeapSnapshotObjectNoData,
         HeapSnapshotObjectNullData;
 
-const String vmServiceVersion = '4.16.0';
+const String vmServiceVersion = '4.17.0';
 
 /// @optional
 const String optional = 'optional';
@@ -385,6 +385,9 @@ class VmService {
   Stream<Event> get onHeapSnapshotEvent =>
       _getEventController('HeapSnapshot').stream;
 
+  // TimerSignificantlyOverdue
+  Stream<Event> get onTimerEvent => _getEventController('Timer').stream;
+
   // WriteEvent
   Stream<Event> get onStdoutEvent => _getEventController('Stdout').stream;
 
@@ -1830,6 +1833,7 @@ class VmService {
   /// Logging | Logging
   /// Service | ServiceRegistered, ServiceUnregistered
   /// HeapSnapshot | HeapSnapshot
+  /// Timer | TimerSignificantlyOverdue
   ///
   /// Additionally, some embedders provide the `Stdout` and `Stderr` streams.
   /// These streams allow the client to subscribe to writes to stdout and
@@ -2292,6 +2296,7 @@ abstract class EventStreams {
   static const String kLogging = 'Logging';
   static const String kService = 'Service';
   static const String kHeapSnapshot = 'HeapSnapshot';
+  static const String kTimer = 'Timer';
   static const String kStdout = 'Stdout';
   static const String kStderr = 'Stderr';
 }
@@ -3950,6 +3955,16 @@ class Event extends Response {
   @optional
   LogRecord? logRecord;
 
+  /// Details about this event.
+  ///
+  /// For events of kind TimerSignifcantlyOverdue, this is a message stating how
+  /// many milliseconds late the timer fired, and giving possible reasons for
+  /// why it fired late.
+  ///
+  /// Only provided for events of kind TimerSignificantlyOverdue.
+  @optional
+  String? details;
+
   /// The service identifier.
   ///
   /// This is provided for the event kinds:
@@ -4035,6 +4050,7 @@ class Event extends Response {
     this.status,
     this.reloadFailureReason,
     this.logRecord,
+    this.details,
     this.service,
     this.method,
     this.alias,
@@ -4085,6 +4101,7 @@ class Event extends Response {
     reloadFailureReason = json['reloadFailureReason'];
     logRecord = createServiceObject(json['logRecord'], const ['LogRecord'])
         as LogRecord?;
+    details = json['details'];
     service = json['service'];
     method = json['method'];
     alias = json['alias'];
@@ -4143,6 +4160,7 @@ class Event extends Response {
           'reloadFailureReason': reloadFailureReasonValue,
         if (logRecord?.toJson() case final logRecordValue?)
           'logRecord': logRecordValue,
+        if (details case final detailsValue?) 'details': detailsValue,
         if (service case final serviceValue?) 'service': serviceValue,
         if (method case final methodValue?) 'method': methodValue,
         if (alias case final aliasValue?) 'alias': aliasValue,

pkg/vm_service/test/overdue_timer_detection_test.dart

@@ -0,0 +1,66 @@
+// 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:io' show sleep;
+
+import 'package:test/test.dart';
+import 'package:vm_service/vm_service.dart';
+
+import 'common/service_test_common.dart';
+import 'common/test_helper.dart';
+
+Future<void> testeeMain() async {
+  final completer = Completer<void>();
+  late final Timer t;
+  t = Timer(
+    const Duration(milliseconds: 100),
+    () {
+      t.cancel();
+      completer.complete();
+    },
+  );
+
+  // Sleep for 201 ms to force [t] to fire at least 100 ms late. This allows us
+  // to expect to receive at least one 'TimerSignificantlyOverdue' event in
+  // [tests] below, because a 'TimerSignificantlyOverdue' event should be fired
+  // whenever a timer is identified to be at least 100 ms overdue.
+  sleep(const Duration(milliseconds: 201));
+  await completer.future;
+}
+
+final tests = <IsolateTest>[
+  hasPausedAtStart,
+  (VmService service, IsolateRef isolateRef) async {
+    final completer = Completer<void>();
+    late final StreamSubscription<Event> sub;
+    sub = service.onTimerEvent.listen((Event event) async {
+      if (event.kind == 'TimerSignificantlyOverdue') {
+        final detailsRegex = RegExp(
+          r'A timer should have fired (\d+) ms ago, but just fired now.',
+        );
+        final millisecondsOverdueAsString =
+            detailsRegex.firstMatch(event.details!)!.group(1)!;
+        expect(
+          int.parse(millisecondsOverdueAsString),
+          greaterThanOrEqualTo(100),
+        );
+        await sub.cancel();
+        completer.complete();
+      }
+    });
+    await service.streamListen(EventStreams.kTimer);
+
+    await service.resume(isolateRef.id!);
+    await completer.future;
+  },
+];
+
+Future<void> main([args = const <String>[]]) => runIsolateTests(
+      args,
+      tests,
+      'overdue_timer_detection_test.dart',
+      testeeConcurrent: testeeMain,
+      pauseOnStart: true,
+    );

pkg/vm_service_interface/lib/src/vm_service_interface.dart

@@ -17,7 +17,7 @@ import 'service_extension_registry.dart';
 
 export 'service_extension_registry.dart' show ServiceExtensionRegistry;
 
-const String vmServiceVersion = '4.16.0';
+const String vmServiceVersion = '4.17.0';
 
 /// A class representation of the Dart VM Service Protocol.
 abstract interface class VmServiceInterface {
@@ -1292,6 +1292,7 @@ abstract interface class VmServiceInterface {
   /// Logging | Logging
   /// Service | ServiceRegistered, ServiceUnregistered
   /// HeapSnapshot | HeapSnapshot
+  /// Timer | TimerSignificantlyOverdue
   ///
   /// Additionally, some embedders provide the `Stdout` and `Stderr` streams.
   /// These streams allow the client to subscribe to writes to stdout and

runtime/docs/detecting_bugs_in_the_implementation_of_timers.md

@@ -0,0 +1,35 @@
+# Detecting Bugs in the Implementation of Timers
+
+When an app is connected to DevTools, a message will appear in the Logging view
+of DevTools whenever a timer in the app fires at least 100 ms late.
+
+<!-- // TODO(derekxu16): Insert a screenshot of DevTools displaying these messages. -->
+
+As the messages in the screenshot state, the appearance of these messages does
+not necessarily mean that there is a bug in the implementation of timers. Timers
+can be blocked from firing for other reasons. A stretch of uninterruptible
+synchronous operations can block asynchronous operations, or an app can be
+frozen by the OS to conserve resources. When "late timer" messages appear, these
+other causes must be ruled out before before suspecting that there is a bug in
+the implementation of timers.
+
+Be wary of the fact that it is possible for a bug in the implementation of
+timers to manifest only by increasing the delay length of timers that would have
+also been delayed under normal circumstances. For example,
+[this bug in the implementation of timers on Android](https://github.com/dart-lang/sdk/issues/54868)
+only manifested after a given Android app was put into and then taken out of the
+Android cached apps freezer. One would have had to join the information logged
+in DevTools with information logged by the Android platform to discover this
+bug. The following is an explanation of how this could have been done.
+
+Consider an app that was put into and taken out of the cached apps freezer. The
+times at which the app was put into and taken out of the cached apps freezer
+will be available in `logcat`.
+[This link](https://source.android.com/docs/core/perf/cached-apps-freezer#testing-the-apps-freezer)
+explains how to find those times. Let those times be `f_in` and `f_out`. There
+will be messages in DevTools that say "A timer was supposed to fire `x_i` ms
+ago, but just fired now...". The time at which each message was logged will also
+be shown in DevTools; let these time be `m_i`. If a message exists such that
+(`f_in` <= `m_i` - `x_i` <= `f_out`) AND (`x_i` >= `f_out` - `f_in`), and other
+asynchronous operations blockers can be ruled out, then it means that there is a
+bug in the implementation of timers.

runtime/lib/isolate.cc

@@ -1392,4 +1392,16 @@ DEFINE_NATIVE_ENTRY(TransferableTypedData_materialize, 0, 1) {
   return typed_data.ptr();
 }
 
+DEFINE_NATIVE_ENTRY(Timer_postTimerEvent, 0, 1) {
+#if !defined(PRODUCT)
+  GET_NON_NULL_NATIVE_ARGUMENT(Integer, milliseconds_overdue,
+                               arguments->NativeArgAt(0));
+  // |milliseconds_overdue| can get truncated on 32-bit platforms, but in
+  // practice, it should never get close to |INT_MAX|.
+  Service::SendTimerEvent(isolate,
+                          static_cast<intptr_t>(milliseconds_overdue.Value()));
+#endif  // !defined(PRODUCT)
+  return Object::null();
+}
+
 }  // namespace dart

runtime/observatory/tests/service/get_version_rpc_test.dart

@@ -12,7 +12,7 @@ var tests = <VMTest>[
     final result = await vm.invokeRpcNoUpgrade('getVersion', {});
     expect(result['type'], 'Version');
     expect(result['major'], 4);
-    expect(result['minor'], 16);
+    expect(result['minor'], 17);
     expect(result['_privateMajor'], 0);
     expect(result['_privateMinor'], 0);
   },

runtime/vm/bootstrap_natives.h

@@ -312,7 +312,8 @@ namespace dart {
   V(DartApiDLMinorVersion, 0)                                                  \
   V(DartNativeApiFunctionPointer, 1)                                           \
   V(TransferableTypedData_factory, 2)                                          \
-  V(TransferableTypedData_materialize, 1)
+  V(TransferableTypedData_materialize, 1)                                      \
+  V(Timer_postTimerEvent, 1)
 
 // List of bootstrap native entry points used in the dart:mirror library.
 #define MIRRORS_BOOTSTRAP_NATIVE_LIST(V)                                       \

runtime/vm/service.cc

@@ -480,6 +480,7 @@ StreamInfo Service::gc_stream("GC");
 StreamInfo Service::echo_stream("_Echo");
 StreamInfo Service::heapsnapshot_stream("HeapSnapshot");
 StreamInfo Service::logging_stream("Logging");
+StreamInfo Service::timer_stream("Timer");
 StreamInfo Service::extension_stream("Extension");
 StreamInfo Service::timeline_stream("Timeline");
 StreamInfo Service::profiler_stream("Profiler");
@@ -490,11 +491,12 @@ intptr_t Service::dart_library_kernel_len_ = 0;
 // Keep streams_ in sync with the protected streams in
 // lib/developer/extension.dart
 static StreamInfo* const streams_[] = {
-    &Service::vm_stream,       &Service::isolate_stream,
-    &Service::debug_stream,    &Service::gc_stream,
-    &Service::echo_stream,     &Service::heapsnapshot_stream,
-    &Service::logging_stream,  &Service::extension_stream,
-    &Service::timeline_stream, &Service::profiler_stream,
+    &Service::vm_stream,        &Service::isolate_stream,
+    &Service::debug_stream,     &Service::gc_stream,
+    &Service::echo_stream,      &Service::heapsnapshot_stream,
+    &Service::logging_stream,   &Service::timer_stream,
+    &Service::extension_stream, &Service::timeline_stream,
+    &Service::profiler_stream,
 };
 
 bool Service::ListenStream(const char* stream_id,
@@ -5106,12 +5108,18 @@ void Service::SendLogEvent(Isolate* isolate,
   Service::HandleEvent(&event);
 }
 
+void Service::SendTimerEvent(Isolate* isolate, intptr_t milliseconds_overdue) {
+  if (!Service::timer_stream.enabled()) {
+    return;
+  }
+  ServiceEvent event(isolate, ServiceEvent::kTimerSignificantlyOverdue);
+  event.set_milliseconds_overdue(milliseconds_overdue);
+  Service::HandleEvent(&event);
+}
+
 void Service::SendExtensionEvent(Isolate* isolate,
                                  const String& event_kind,
                                  const String& event_data) {
-  if (!Service::extension_stream.enabled()) {
-    return;
-  }
   ServiceEvent::ExtensionEvent extension_event;
   extension_event.event_kind = &event_kind;
   extension_event.event_data = &event_data;