Correct units and cumulative bug in GC times (#9890)
Fixes #7080
In the logging page, GC events were displayed with summaries like idle
collection in 290 ms. The value 290 was calculated directly from the cumulative
times (`newSpace.time` and `oldSpace.time`), meaning it represented the total
cumulative GC time since isolate startup rather than the duration of this
specific GC. In reality, the individual collection took 290 microseconds (which
is 0.29 milliseconds), but since it was displaying the cumulative time of 290
ms, it was off by a factor of 1000x.
In this fix, we update `_handleGCEvent` to track and subtract the previous
cumulative GC time from the new cumulative GC time to compute the actual
duration delta for this specific GC.
Also format the duration as a millisecond double with 1 decimal place
(consistent with how frame times are displayed), and appended it to the log
summary (e.g. "idle collection in 100.0 ms").
diff --git a/packages/devtools_app/lib/src/screens/logging/logging_controller.dart b/packages/devtools_app/lib/src/screens/logging/logging_controller.dart
index da6f1ce..b9b1c16 100644
--- a/packages/devtools_app/lib/src/screens/logging/logging_controller.dart
+++ b/packages/devtools_app/lib/src/screens/logging/logging_controller.dart
@@ -240,6 +240,13 @@
late final LogDetailsController logDetailsController;
+ /// Tracks the previous cumulative GC times (in seconds) for each active isolate.
+ ///
+ /// This is used to compute the actual duration of the current GC event (by taking
+ /// the delta between consecutive cumulative times), rather than displaying the
+ /// total cumulative GC time.
+ final _previousGcTimesByIsolate = <String, double>{};
+
List<LogData> data = <LogData>[];
final selectedLog = ValueNotifier<LogData?>(null);
@@ -288,6 +295,7 @@
void clear() {
_updateData([]);
+ _previousGcTimesByIsolate.clear();
serviceConnection.errorBadgeManager.clearErrorCount(LoggingScreen.id);
}
@@ -455,11 +463,24 @@
final usedBytes = newSpace.used! + oldSpace.used!;
final capacityBytes = newSpace.capacity! + oldSpace.capacity!;
- final time = ((newSpace.time! + oldSpace.time!) * 1000).round();
+ final isolateId = e.isolate?.id;
+ // Cumulative time, in seconds.
+ final newCumulativeTime = newSpace.time! + oldSpace.time!;
+
+ String durationText = '';
+ if (isolateId != null) {
+ final previousGcTime = _previousGcTimesByIsolate[isolateId];
+ _previousGcTimesByIsolate[isolateId] = newCumulativeTime;
+ if (previousGcTime != null && newCumulativeTime >= previousGcTime) {
+ // Multiply by 1000 to display in milliseconds.
+ final durationMs = (newCumulativeTime - previousGcTime) * 1000;
+ durationText = ' in ${durationMs.toStringAsFixed(1)} ms';
+ }
+ }
final summary =
'${isolateRef['name']} • '
- '${e.json!['reason']} collection in $time ms • '
+ '${e.json!['reason']} collection$durationText • '
'${printBytes(usedBytes, unit: ByteUnit.mb, includeUnit: true)} used of '
'${printBytes(capacityBytes, unit: ByteUnit.mb, includeUnit: true)}';
diff --git a/packages/devtools_app/release_notes/NEXT_RELEASE_NOTES.md b/packages/devtools_app/release_notes/NEXT_RELEASE_NOTES.md
index 381298f..8c84a48 100644
--- a/packages/devtools_app/release_notes/NEXT_RELEASE_NOTES.md
+++ b/packages/devtools_app/release_notes/NEXT_RELEASE_NOTES.md
@@ -45,7 +45,8 @@
## Logging updates
-TODO: Remove this section if there are not any updates.
+* Correct time units and cumulative nature of GC events.
+ [#9890](https://github.com/flutter/devtools/pull/9890)
## App size tool updates
diff --git a/packages/devtools_app/test/screens/logging/logging_controller_test.dart b/packages/devtools_app/test/screens/logging/logging_controller_test.dart
index 85b534e..f906aff 100644
--- a/packages/devtools_app/test/screens/logging/logging_controller_test.dart
+++ b/packages/devtools_app/test/screens/logging/logging_controller_test.dart
@@ -19,6 +19,42 @@
void main() {
var timestampCounter = 0;
+ Event gcEvent({
+ required double newTime,
+ required double oldTime,
+ required String isolateId,
+ }) => Event.parse({
+ 'kind': EventKind.kGC,
+ 'timestamp': ++timestampCounter,
+ 'isolate': {
+ 'type': '@Isolate',
+ 'id': isolateId,
+ 'name': 'main',
+ 'number': '1',
+ },
+ 'reason': 'idle',
+ 'new': {
+ 'type': 'HeapSpace',
+ 'name': 'new',
+ 'collections': 1,
+ 'avgCollectionPeriodMillis': 100.0,
+ 'used': 1024,
+ 'capacity': 2048,
+ 'external': 0,
+ 'time': newTime,
+ },
+ 'old': {
+ 'type': 'HeapSpace',
+ 'name': 'old',
+ 'collections': 1,
+ 'avgCollectionPeriodMillis': 100.0,
+ 'used': 4096,
+ 'capacity': 8192,
+ 'external': 0,
+ 'time': oldTime,
+ },
+ })!;
+
group('LoggingController', () {
late LoggingController controller;
@@ -194,6 +230,94 @@
expect(controller.filteredData.value, isEmpty);
});
+ test('GC events track duration delta', () async {
+ final fakeService =
+ serviceConnection.serviceManager.service as FakeVmServiceWrapper;
+
+ expect(controller.data, isEmpty);
+
+ // First GC event: baseline established, no duration printed.
+ fakeService.emitGCEvent(
+ event: gcEvent(newTime: 0.1, oldTime: 0.2, isolateId: 'isolates/123'),
+ );
+ await Future<void>.delayed(const Duration(milliseconds: 10));
+
+ expect(controller.data, hasLength(1));
+ expect(
+ controller.data.first.summary,
+ 'main • idle collection • 0.0 MB used of 0.0 MB',
+ );
+
+ // Second GC event: delta is
+ // (0.15 + 0.25) - (0.1 + 0.2) = 0.4 - 0.3 = 0.1s = 100ms.
+ fakeService.emitGCEvent(
+ event: gcEvent(newTime: 0.15, oldTime: 0.25, isolateId: 'isolates/123'),
+ );
+ await Future<void>.delayed(const Duration(milliseconds: 10));
+
+ expect(controller.data, hasLength(2));
+ expect(
+ controller.data[1].summary,
+ 'main • idle collection in 100.0 ms • 0.0 MB used of 0.0 MB',
+ );
+
+ // Third GC event on a different isolate: no baseline yet, so no duration
+ // printed.
+ fakeService.emitGCEvent(
+ event: gcEvent(newTime: 0.05, oldTime: 0.05, isolateId: 'isolates/456'),
+ );
+ await Future<void>.delayed(const Duration(milliseconds: 10));
+
+ expect(controller.data, hasLength(3));
+ expect(
+ controller.data[2].summary,
+ 'main • idle collection • 0.0 MB used of 0.0 MB',
+ );
+
+ // Fourth GC event: clock reset on isolates/123 (cumulative goes from 0.4s to 0.1s).
+ // Since newCumulativeTime (0.1s) < previousGcTime (0.4s), duration delta is skipped,
+ // and baseline is updated to 0.1s.
+ fakeService.emitGCEvent(
+ event: gcEvent(newTime: 0.05, oldTime: 0.05, isolateId: 'isolates/123'),
+ );
+ await Future<void>.delayed(const Duration(milliseconds: 10));
+
+ expect(controller.data, hasLength(4));
+ expect(
+ controller.data[3].summary,
+ 'main • idle collection • 0.0 MB used of 0.0 MB',
+ );
+
+ // Fifth GC event: delta since reset baseline (0.1s) is (0.08 + 0.12) - 0.1 = 0.2 - 0.1 = 0.1s = 100ms.
+ fakeService.emitGCEvent(
+ event: gcEvent(newTime: 0.08, oldTime: 0.12, isolateId: 'isolates/123'),
+ );
+ await Future<void>.delayed(const Duration(milliseconds: 10));
+
+ expect(controller.data, hasLength(5));
+ expect(
+ controller.data[4].summary,
+ 'main • idle collection in 100.0 ms • 0.0 MB used of 0.0 MB',
+ );
+
+ // Clear logs: resets baselines.
+ controller.clear();
+ expect(controller.data, isEmpty);
+
+ // Sixth GC event (same isolate as first): baseline was cleared, so no
+ // duration printed.
+ fakeService.emitGCEvent(
+ event: gcEvent(newTime: 0.2, oldTime: 0.3, isolateId: 'isolates/123'),
+ );
+ await Future<void>.delayed(const Duration(milliseconds: 10));
+
+ expect(controller.data, hasLength(1));
+ expect(
+ controller.data.first.summary,
+ 'main • idle collection • 0.0 MB used of 0.0 MB',
+ );
+ });
+
test('matchesForSearch - default filters', () {
prepareTestLogs();
diff --git a/packages/devtools_test/lib/src/mocks/fake_vm_service_wrapper.dart b/packages/devtools_test/lib/src/mocks/fake_vm_service_wrapper.dart
index d6a981e..0df17c7 100644
--- a/packages/devtools_test/lib/src/mocks/fake_vm_service_wrapper.dart
+++ b/packages/devtools_test/lib/src/mocks/fake_vm_service_wrapper.dart
@@ -128,30 +128,25 @@
}
@override
- Future<UriList> lookupPackageUris(String isolateId, List<String> uris) {
- return Future.value(
- UriList(
- uris: _resolvedUriMap != null
- ? (uris.map((e) => _resolvedUriMap[e]).toList())
- : null,
- ),
- );
- }
+ Future<UriList> lookupPackageUris(
+ String isolateId,
+ List<String> uris,
+ ) => Future.syncValue(UriList(
+ uris: _resolvedUriMap != null
+ ? (uris.map((e) => _resolvedUriMap[e]).toList())
+ : null
+ ));
@override
Future<UriList> lookupResolvedPackageUris(
String isolateId,
List<String> uris, {
bool? local,
- }) {
- return Future.value(
- UriList(
- uris: _reverseResolvedUriMap != null
- ? (uris.map((e) => _reverseResolvedUriMap[e]).toList())
- : null,
- ),
- );
- }
+ }) => Future.syncValue(UriList(
+ uris: _reverseResolvedUriMap != null
+ ? (uris.map((e) => _reverseResolvedUriMap[e]).toList())
+ : null,
+ ));
@override
String get wsUri => 'ws://127.0.0.1:56137/ISsyt6ki0no=/ws';
@@ -190,14 +185,14 @@
allocationProfile.json = allocationProfile.toJson();
// Fake GC statistics
allocationProfile.json![AllocationProfilePrivateViewExtension.heapsKey] =
- <String, dynamic>{
- AllocationProfilePrivateViewExtension.newSpaceKey: <String, dynamic>{
+ <String, Object?>{
+ AllocationProfilePrivateViewExtension.newSpaceKey: <String, Object?>{
GCStats.usedKey: 1234,
GCStats.capacityKey: 12345,
GCStats.collectionsKey: 42,
GCStats.timeKey: 69,
},
- AllocationProfilePrivateViewExtension.oldSpaceKey: <String, dynamic>{
+ AllocationProfilePrivateViewExtension.oldSpaceKey: <String, Object?>{
GCStats.usedKey: 4321,
GCStats.capacityKey: 54321,
GCStats.collectionsKey: 24,
@@ -522,8 +517,8 @@
@override
Stream<Event> get onGCEvent => _gcEventStream.stream;
- void emitGCEvent() {
- _gcEventStream.sink.add(Event(kind: EventKind.kGC));
+ void emitGCEvent({Event? event}) {
+ _gcEventStream.sink.add(event ?? Event(kind: EventKind.kGC));
}
@override
