Skip to content

Correct units and cumulative bug in GC times #9890

New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Open
srawlins wants to merge 3 commits into
base: master
Choose a base branch
from
Open

Correct units and cumulative bug in GC times #9890

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
3 commits
Select commit Hold shift + click to select a range
90d513c
Correct units and cumulative bug in GC times
srawlins Jun 23, 2026
928667f
fixes
srawlins Jul 13, 2026
9a9220d
rel-notes
srawlins Jul 14, 2026
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
25 changes: 23 additions & 2 deletions packages/devtools_app/lib/src/screens/logging/logging_controller.dart
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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>{};
Comment on lines +243 to +248

@gemini-code-assist gemini-code-assist Bot Jul 13, 2026

Copy link
Copy Markdown
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

medium

[CONCERN] The _previousGcTimesByIsolate map tracks cumulative GC times for each active isolate, but entries are never removed when an isolate exits. In applications that spawn and destroy many short-lived isolates, this can lead to a memory leak. Consider cleaning up the map when isolates are destroyed (e.g., by listening to isolate exit events via the IsolateManager).

References
  1. Categorize Severity: Prefix every comment with a severity like [CONCERN] for maintainability issues. (link)


List<LogData> data = <LogData>[];

final selectedLog = ValueNotifier<LogData?>(null);
Expand Down Expand Up @@ -288,6 +295,7 @@ class LoggingController extends DevToolsScreenController

void clear() {
_updateData([]);
_previousGcTimesByIsolate.clear();
serviceConnection.errorBadgeManager.clearErrorCount(LoggingScreen.id);
}

Expand Down Expand Up @@ -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';
}
}
Comment thread
srawlins marked this conversation as resolved.

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)}';

Expand Down
3 changes: 2 additions & 1 deletion packages/devtools_app/release_notes/NEXT_RELEASE_NOTES.md
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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

Expand Down
124 changes: 124 additions & 0 deletions packages/devtools_app/test/screens/logging/logging_controller_test.dart
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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;

Expand Down Expand Up @@ -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();

Expand Down
41 changes: 18 additions & 23 deletions packages/devtools_test/lib/src/mocks/fake_vm_service_wrapper.dart
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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
));
Comment thread
srawlins marked this conversation as resolved.

@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,
));
Comment thread
srawlins marked this conversation as resolved.

@override
String get wsUri => 'ws://127.0.0.1:56137/ISsyt6ki0no=/ws';
Expand Down Expand Up @@ -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,
Expand Down Expand Up @@ -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
Expand Down
Loading