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").

Author: srawlins

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 = <String, double>{};
+
   List<LogData> data = <LogData>[];
 
   final selectedLog = ValueNotifier<LogData?>(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 && 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)}';
 

packages/devtools_app/release_notes/NEXT_RELEASE_NOTES.md

@@ -45,7 +45,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
 

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,94 @@ 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<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();
 

packages/devtools_test/lib/src/mocks/fake_vm_service_wrapper.dart

@@ -128,30 +128,25 @@ class FakeVmServiceWrapper extends Fake implements VmServiceWrapper {
   }
 
   @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 @@ class FakeVmServiceWrapper extends Fake implements VmServiceWrapper {
     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 @@ class FakeVmServiceWrapper extends Fake implements VmServiceWrapper {
   @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