diff --git a/packages/flutter_driver/lib/src/driver/gc_summarizer.dart b/packages/flutter_driver/lib/src/driver/gc_summarizer.dart new file mode 100644 index 00000000000..2779e782fc7 --- /dev/null +++ b/packages/flutter_driver/lib/src/driver/gc_summarizer.dart @@ -0,0 +1,59 @@ +// Copyright 2014 The Flutter Authors. All rights reserved. +// Use of this source code is governed by a BSD-style license that can be +// found in the LICENSE file. + +import 'timeline.dart'; + +/// GC related timeline events. +/// +/// All these events occur only on the UI thread and are non overlapping. +const Set kGCRootEvents = { + 'CollectNewGeneration', + 'CollectOldGeneration', + 'EvacuateNewGeneration', + 'StartConcurrentMark', +}; + +/// Summarizes [TimelineEvents]s corresponding to [kGCRootEvents] category. +/// +/// A sample event (some fields have been omitted for brevity): +/// ``` +/// { +/// "name": "StartConcurrentMarking", +/// "cat": "GC", +/// "ts": 3240710599608, +/// } +/// ``` +/// This class provides methods to compute the total time spend in GC on +/// the UI thread. +class GCSummarizer { + GCSummarizer._(this.totalGCTimeMillis); + + /// Creates a [GCSummarizer] given the timeline events. + static GCSummarizer fromEvents(List gcEvents) { + double totalGCTimeMillis = 0; + TimelineEvent? lastGCBeginEvent; + + for (final TimelineEvent event in gcEvents) { + if (!kGCRootEvents.contains(event.name)) { + continue; + } + if (event.phase == 'B') { + lastGCBeginEvent = event; + } else if (lastGCBeginEvent != null) { + // These events must not overlap. + assert(event.name == lastGCBeginEvent.name, + 'Expected "${lastGCBeginEvent.name}" got "${event.name}"'); + final double st = lastGCBeginEvent.timestampMicros!.toDouble(); + final double end = event.timestampMicros!.toDouble(); + lastGCBeginEvent = null; + totalGCTimeMillis += (end - st) / 1000; + } + } + + return GCSummarizer._(totalGCTimeMillis); + } + + /// Total time spent doing GC on the UI thread. + final double totalGCTimeMillis; +} diff --git a/packages/flutter_driver/lib/src/driver/timeline_summary.dart b/packages/flutter_driver/lib/src/driver/timeline_summary.dart index d766c7196de..73af4ae637a 100644 --- a/packages/flutter_driver/lib/src/driver/timeline_summary.dart +++ b/packages/flutter_driver/lib/src/driver/timeline_summary.dart @@ -9,6 +9,7 @@ import 'package:file/file.dart'; import 'package:path/path.dart' as path; import 'common.dart'; +import 'gc_summarizer.dart'; import 'percentile_utils.dart'; import 'profiling_summarizer.dart'; import 'raster_cache_summarizer.dart'; @@ -218,6 +219,7 @@ class TimelineSummary { final VsyncFrameLagSummarizer vsyncFrameLagSummarizer = _vsyncFrameLagSummarizer(); final Map profilingSummary = _profilingSummarizer().summarize(); final RasterCacheSummarizer rasterCacheSummarizer = _rasterCacheSummarizer(); + final GCSummarizer gcSummarizer = _gcSummarizer(); final Map timelineSummary = { 'average_frame_build_time_millis': computeAverageFrameBuildTimeMillis(), @@ -268,6 +270,7 @@ class TimelineSummary { '90th_percentile_picture_cache_memory': rasterCacheSummarizer.computePercentilePictureMemory(90.0), '99th_percentile_picture_cache_memory': rasterCacheSummarizer.computePercentilePictureMemory(99.0), 'worst_picture_cache_memory': rasterCacheSummarizer.computeWorstPictureMemory(), + 'total_ui_gc_time': gcSummarizer.totalGCTimeMillis, }; timelineSummary.addAll(profilingSummary); @@ -432,4 +435,6 @@ class TimelineSummary { VsyncFrameLagSummarizer _vsyncFrameLagSummarizer() => VsyncFrameLagSummarizer(_extractEventsWithNames(kVsyncTimelineEventNames)); RasterCacheSummarizer _rasterCacheSummarizer() => RasterCacheSummarizer(_extractNamedEvents(kRasterCacheEvent)); + + GCSummarizer _gcSummarizer() => GCSummarizer.fromEvents(_extractEventsWithNames(kGCRootEvents)); } diff --git a/packages/flutter_driver/test/src/real_tests/timeline_summary_test.dart b/packages/flutter_driver/test/src/real_tests/timeline_summary_test.dart index b7456cf8ada..38131e7af99 100644 --- a/packages/flutter_driver/test/src/real_tests/timeline_summary_test.dart +++ b/packages/flutter_driver/test/src/real_tests/timeline_summary_test.dart @@ -95,37 +95,36 @@ void main() { 'ts': timeStamp, }; - List> newGenGC(int count) => List>.filled( - count, - { - 'name': 'CollectNewGeneration', - 'cat': 'GC', - 'tid': 19695, - 'pid': 19650, - 'ts': 358849612473, - 'tts': 476761, - 'ph': 'B', - 'args': { - 'isolateGroupId': 'isolateGroups/10824099774666259225', - }, - }, - ); + List> _genGC(String name, int count, int startTime, int timeDiff) { + int ts = startTime; + bool begin = true; + final List> ret = >[]; + for (int i = 0; i < count; i++) { + ret.add({ + 'name': name, + 'cat': 'GC', + 'tid': 19695, + 'pid': 19650, + 'ts': ts, + 'tts': ts, + 'ph': begin ? 'B' : 'E', + 'args': { + 'isolateGroupId': 'isolateGroups/10824099774666259225', + }, + }); + ts = ts + timeDiff; + begin = !begin; + } + return ret; + } - List> oldGenGC(int count) => List>.filled( - count, - { - 'name': 'CollectOldGeneration', - 'cat': 'GC', - 'tid': 19695, - 'pid': 19650, - 'ts': 358849612473, - 'tts': 476761, - 'ph': 'B', - 'args': { - 'isolateGroupId': 'isolateGroups/10824099774666259225', - }, - }, - ); + List> newGenGC(int count, int startTime, int timeDiff) { + return _genGC('CollectNewGeneration', count, startTime, timeDiff); + } + + List> oldGenGC(int count, int startTime, int timeDiff) { + return _genGC('CollectOldGeneration', count, startTime, timeDiff); + } List> rasterizeTimeSequenceInMillis(List sequence) { final List> result = >[]; @@ -420,8 +419,8 @@ void main() { begin(1000), end(19000), begin(19000), end(29000), begin(29000), end(49000), - ...newGenGC(4), - ...oldGenGC(5), + ...newGenGC(4, 10, 100), + ...oldGenGC(5, 10000, 100), frameBegin(1000), frameEnd(18000), frameBegin(19000), frameEnd(28000), frameBegin(29000), frameEnd(48000), @@ -467,6 +466,7 @@ void main() { '90th_percentile_picture_cache_memory': 0.0, '99th_percentile_picture_cache_memory': 0.0, 'worst_picture_cache_memory': 0.0, + 'total_ui_gc_time': 0.4, }, ); }); @@ -526,8 +526,8 @@ void main() { lagBegin(1000, 4), lagEnd(2000, 4), lagBegin(1200, 12), lagEnd(2400, 12), lagBegin(4200, 8), lagEnd(9400, 8), - ...newGenGC(4), - ...oldGenGC(5), + ...newGenGC(4, 10, 100), + ...oldGenGC(5, 10000, 100), cpuUsage(5000, 20), cpuUsage(5010, 60), memoryUsage(6000, 20, 40), memoryUsage(6100, 30, 45), platformVsync(7000), vsyncCallback(7500), @@ -581,6 +581,7 @@ void main() { '90th_percentile_picture_cache_memory': 0.0, '99th_percentile_picture_cache_memory': 0.0, 'worst_picture_cache_memory': 0.0, + 'total_ui_gc_time': 0.4, }); }); });