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..b9b1c163a51 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 && 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 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 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..f906aff3389 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,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.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', + ); + + // 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); + + // 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.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