From 90d513ccea945b334f3695554a02c68a95c7d396 Mon Sep 17 00:00:00 2001 From: Sam Rawlins Date: Tue, 23 Jun 2026 11:28:35 -0700 Subject: [PATCH 1/3] Correct units and cumulative bug in GC times 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"). --- .../screens/logging/logging_controller.dart | 25 ++++- .../logging/logging_controller_test.dart | 98 +++++++++++++++++++ .../src/mocks/fake_vm_service_wrapper.dart | 41 ++++---- 3 files changed, 139 insertions(+), 25 deletions(-) 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 da6f1cedf8f..fb8478f7a10 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 @@ class LoggingController extends DevToolsScreenController 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 = {}; + List data = []; final selectedLog = ValueNotifier(null); @@ -288,6 +295,7 @@ class LoggingController extends DevToolsScreenController void clear() { _updateData([]); + _previousGcTimesByIsolate.clear(); serviceConnection.errorBadgeManager.clearErrorCount(LoggingScreen.id); } @@ -455,11 +463,24 @@ class LoggingController extends DevToolsScreenController 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) { + // 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/test/screens/logging/logging_controller_test.dart b/packages/devtools_app/test/screens/logging/logging_controller_test.dart index 85b534e7741..33363923746 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 @@ import 'package:vm_service/vm_service.dart'; 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,68 @@ void main() { 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.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.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.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', + ); + + // Clear logs: resets baselines. + controller.clear(); + expect(controller.data, isEmpty); + + // Fourth 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.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 d6a981edc81..0df17c7f325 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 @@ class FakeVmServiceWrapper extends Fake implements VmServiceWrapper { } @override - Future lookupPackageUris(String isolateId, List uris) { - return Future.value( - UriList( - uris: _resolvedUriMap != null - ? (uris.map((e) => _resolvedUriMap[e]).toList()) - : null, - ), - ); - } + Future lookupPackageUris( + String isolateId, + List uris, + ) => Future.syncValue(UriList( + uris: _resolvedUriMap != null + ? (uris.map((e) => _resolvedUriMap[e]).toList()) + : null + )); @override Future lookupResolvedPackageUris( String isolateId, List 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 @@ class FakeVmServiceWrapper extends Fake implements VmServiceWrapper { allocationProfile.json = allocationProfile.toJson(); // Fake GC statistics allocationProfile.json![AllocationProfilePrivateViewExtension.heapsKey] = - { - AllocationProfilePrivateViewExtension.newSpaceKey: { + { + AllocationProfilePrivateViewExtension.newSpaceKey: { GCStats.usedKey: 1234, GCStats.capacityKey: 12345, GCStats.collectionsKey: 42, GCStats.timeKey: 69, }, - AllocationProfilePrivateViewExtension.oldSpaceKey: { + AllocationProfilePrivateViewExtension.oldSpaceKey: { GCStats.usedKey: 4321, GCStats.capacityKey: 54321, GCStats.collectionsKey: 24, @@ -522,8 +517,8 @@ class FakeVmServiceWrapper extends Fake implements VmServiceWrapper { @override Stream 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 From 928667f5d62f296b1e1b3461aab3c672376abf6a Mon Sep 17 00:00:00 2001 From: Sam Rawlins Date: Mon, 13 Jul 2026 16:23:23 -0700 Subject: [PATCH 2/3] fixes --- .../screens/logging/logging_controller.dart | 2 +- .../logging/logging_controller_test.dart | 28 ++++++++++++++++++- 2 files changed, 28 insertions(+), 2 deletions(-) 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 fb8478f7a10..b9b1c163a51 100644 --- a/packages/devtools_app/lib/src/screens/logging/logging_controller.dart +++ b/packages/devtools_app/lib/src/screens/logging/logging_controller.dart @@ -471,7 +471,7 @@ class LoggingController extends DevToolsScreenController if (isolateId != null) { final previousGcTime = _previousGcTimesByIsolate[isolateId]; _previousGcTimesByIsolate[isolateId] = newCumulativeTime; - if (previousGcTime != null) { + if (previousGcTime != null && newCumulativeTime >= previousGcTime) { // Multiply by 1000 to display in milliseconds. final durationMs = (newCumulativeTime - previousGcTime) * 1000; durationText = ' in ${durationMs.toStringAsFixed(1)} ms'; 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 33363923746..f906aff3389 100644 --- a/packages/devtools_app/test/screens/logging/logging_controller_test.dart +++ b/packages/devtools_app/test/screens/logging/logging_controller_test.dart @@ -274,11 +274,37 @@ void main() { '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.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.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); - // Fourth GC event (same isolate as first): baseline was cleared, so no + // 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'), From 9a9220dad19506e9703f1bc16735af4c5795d176 Mon Sep 17 00:00:00 2001 From: Sam Rawlins Date: Tue, 14 Jul 2026 13:51:15 -0700 Subject: [PATCH 3/3] rel-notes --- packages/devtools_app/release_notes/NEXT_RELEASE_NOTES.md | 3 ++- 1 file changed, 2 insertions(+), 1 deletion(-) diff --git a/packages/devtools_app/release_notes/NEXT_RELEASE_NOTES.md b/packages/devtools_app/release_notes/NEXT_RELEASE_NOTES.md index ebb8dad9043..97e25d5ea70 100644 --- a/packages/devtools_app/release_notes/NEXT_RELEASE_NOTES.md +++ b/packages/devtools_app/release_notes/NEXT_RELEASE_NOTES.md @@ -43,7 +43,8 @@ TODO: Remove this section if there are not any updates. ## 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