dart-lang/sdk
1
0
Fork 0
Code Issues Pull Requests Actions 2 Packages Projects Releases Wiki Activity

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

Browse Source 
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 <bkonyi@google.com>
Commit-Queue: Derek Xu <derekx@google.com>
This commit is contained in:
Derek Xu
2025-04-14 07:36:31 -07:00
committed by Commit Queue
parent ed54a422c6
commit 1d69b0b980
17 changed files with 223 additions and 20 deletions
Download Patch File Download Diff File Expand all files Collapse all files
pkg/vm_service/CHANGELOG.md
+6
View File
@@ -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
View File
@@ -1 +1 @@
version=4.16
version=4.17
pkg/vm_service/lib/src/vm_service.dart
+19 -1
View File
@@ -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
+66
View File
@@ -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
+2 -1
View File
@@ -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
+35
View File
@@ -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
+12
View File
@@ -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
+1 -1
View File
@@ -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
+2 -1
View File
@@ -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
+16 -8
View File
@@ -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;
runtime/vm/service.h
+5 -1
View File
@@ -19,7 +19,7 @@
namespace dart {
#define SERVICE_PROTOCOL_MAJOR_VERSION 4
#define SERVICE_PROTOCOL_MINOR_VERSION 16
#define SERVICE_PROTOCOL_MINOR_VERSION 17
class Array;
class EmbedderServiceHandler;
@@ -178,6 +178,9 @@ class Service : public AllStatic {
const Object& error,
const Instance& stack_trace);
// Sends an event of kind |kTimerSignificantlyOverdue|.
static void SendTimerEvent(Isolate* isolate, intptr_t milliseconds_overdue);
static void SendExtensionEvent(Isolate* isolate,
const String& event_kind,
const String& event_data);
@@ -213,6 +216,7 @@ class Service : public AllStatic {
static StreamInfo echo_stream;
static StreamInfo heapsnapshot_stream;
static StreamInfo logging_stream;
static StreamInfo timer_stream;
static StreamInfo extension_stream;
static StreamInfo timeline_stream;
static StreamInfo profiler_stream;
runtime/vm/service/service.md
+14 -1
View File
@@ -1,4 +1,4 @@
# Dart VM Service Protocol 4.16
# Dart VM Service Protocol 4.17
> Please post feedback to the [observatory-discuss group][discuss-list]
@@ -1892,6 +1892,7 @@ Timeline | TimelineEvents, TimelineStreamsSubscriptionUpdate
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
@@ -2602,6 +2603,17 @@ class Event extends Response {
// This is provided for the Logging event.
LogRecord logRecord [optional];
// 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.
string details [optional];
// The service identifier.
//
// This is provided for the event kinds:
@@ -4981,5 +4993,6 @@ version | comments
4.14 | Added `Finalizer`, `NativeFinalizer`, and `FinalizerEntry`.
4.15 | Added `closureReceiver` property to `@Instance` and `Instance`.
4.16 | Added `reloadFailureReason` property to `Event`. Added `createIdZone`, `deleteIdZone`, and `invalidateIdZone` RPCs. Added optional `idZoneId` parameter to `evaluate`, `evaluateInFrame`, `getInboundReferences`, `getInstances`, `getInstancesAsList`, `getObject`, `getRetainingPath`, `getStack`, and `invoke` RPCs.
4.17 | Added `Timer` stream, added `TimerSignificantlyOverdue` event kind, and added `details` property to `Event`.
[discuss-list]: https://groups.google.com/a/dartlang.org/forum/#!forum/observatory-discuss
runtime/vm/service_event.cc
+17
View File
@@ -49,6 +49,7 @@ ServiceEvent::ServiceEvent(IsolateGroup* isolate_group,
gc_stats_(nullptr),
bytes_(nullptr),
bytes_length_(0),
milliseconds_overdue_(0),
timestamp_(OS::GetCurrentTimeMillis()) {
// We should never generate events for the vm isolate as it is never reported
// over the service.
@@ -132,6 +133,8 @@ const char* ServiceEvent::KindAsCString() const {
return embedder_kind();
case kLogging:
return "Logging";
case kTimerSignificantlyOverdue:
return "TimerSignificantlyOverdue";
case kDebuggerSettingsUpdate:
return "_DebuggerSettingsUpdate";
case kIllegal:
@@ -188,6 +191,9 @@ const StreamInfo* ServiceEvent::stream_info() const {
case kLogging:
return &Service::logging_stream;
case kTimerSignificantlyOverdue:
return &Service::timer_stream;
case kExtension:
return &Service::extension_stream;
@@ -304,6 +310,17 @@ void ServiceEvent::PrintJSON(JSONStream* js) const {
logRecord.AddProperty("error", *(log_record_.error));
logRecord.AddProperty("stackTrace", *(log_record_.stack_trace));
}
if (kind() == kTimerSignificantlyOverdue) {
jsobj.AddPropertyF(
"details",
"A timer should have fired %" Pd
" ms ago, but just fired now. This means that timers were blocked from "
"firing for nearly %" Pd
" ms. Some possible causes of this are: asynchronous operations were "
"blocked by uninterruptible synchronous ones, or your program was "
"frozen by the OS to conserve resources.",
milliseconds_overdue(), milliseconds_overdue());
}
if (kind() == kExtension) {
js->AppendSerializedObject("extensionData",
extension_event_.event_data->ToCString());
runtime/vm/service_event.h
+8
View File
@@ -55,6 +55,8 @@ class ServiceEvent {
kLogging,
kTimerSignificantlyOverdue,
kExtension,
kTimelineEvents,
@@ -199,6 +201,11 @@ class ServiceEvent {
void set_log_record(const LogRecord& log_record) { log_record_ = log_record; }
intptr_t milliseconds_overdue() const { return milliseconds_overdue_; }
void set_milliseconds_overdue(int64_t milliseconds_overdue) {
milliseconds_overdue_ = milliseconds_overdue;
}
void set_extension_event(const ExtensionEvent& extension_event) {
extension_event_ = extension_event;
}
@@ -251,6 +258,7 @@ class ServiceEvent {
const uint8_t* bytes_;
intptr_t bytes_length_;
LogRecord log_record_;
intptr_t milliseconds_overdue_;
ExtensionEvent extension_event_;
Profile* cpu_profile_;
int64_t timestamp_;
sdk/lib/_internal/vm/lib/isolate_patch.dart
+1 -1
View File
@@ -6,8 +6,8 @@ import "dart:_internal" show ClassID, VMLibraryHooks, patch;
import "dart:async"
show Completer, Future, Stream, StreamController, StreamSubscription, Timer;
import "dart:collection" show HashMap;
import 'dart:developer' show postEvent;
import "dart:typed_data" show ByteBuffer, TypedData, Uint8List;
/// These are the additional parts of this patch library:
sdk/lib/_internal/vm/lib/timer_impl.dart
+17 -4
View File
@@ -4,6 +4,13 @@
part of "isolate_patch.dart";
/// Posts a VM Service event to the 'Timer' stream of kind
/// 'TimerSignificantlyOverdue'. The event will contain a 'details' property
/// whose value will be a message reporting that a timer was
/// [milliSecondsOverdue] ms overdue.
@pragma("vm:external-name", "Timer_postTimerEvent")
external void _postTimerEvent(int millisecondsOverdue);
// Timer heap implemented as a array-based binary heap[0].
// This allows for O(1) `first`, O(log(n)) `remove`/`removeFirst` and O(log(n))
// `add`.
@@ -387,6 +394,14 @@ class _Timer implements Timer {
var timer = pendingTimers[i];
timer._indexOrNext = null;
final millisecondsOverdue =
VMLibraryHooks.timerMillisecondClock() - timer._wakeupTime;
if (!const bool.fromEnvironment("dart.vm.product") &&
millisecondsOverdue >= 100) {
_postTimerEvent(millisecondsOverdue);
}
// One of the timers in the pending_timers list can cancel
// one of the later timers which will set the callback to
// null. Or the pending zero timer has been canceled earlier.
@@ -397,10 +412,8 @@ class _Timer implements Timer {
timer._callback = null;
} else if (timer._milliSeconds > 0) {
var ms = timer._milliSeconds;
int overdue =
VMLibraryHooks.timerMillisecondClock() - timer._wakeupTime;
if (overdue > ms) {
int missedTicks = overdue ~/ ms;
if (millisecondsOverdue > ms) {
int missedTicks = millisecondsOverdue ~/ ms;
timer._wakeupTime += missedTicks * ms;
timer._tick += missedTicks;
}
sdk/lib/developer/extension.dart
+1
View File
@@ -159,6 +159,7 @@ void postEvent(
'_Echo',
'HeapSnapshot',
'Logging',
'Timer',
'Timeline',
'Profiler',
];