Compute the total time spent on UI thread for GC (#95692)

packages/flutter_driver/lib/src/driver/gc_summarizer.dart

+// 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<String> kGCRootEvents = <String>{
+  '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<TimelineEvent> 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;
+}

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<String, dynamic> profilingSummary = _profilingSummarizer().summarize();
     final RasterCacheSummarizer rasterCacheSummarizer = _rasterCacheSummarizer();
+    final GCSummarizer gcSummarizer = _gcSummarizer();
 
     final Map<String, dynamic> timelineSummary = <String, dynamic>{
       '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));
 }

packages/flutter_driver/test/src/real_tests/timeline_summary_test.dart

@@ -95,37 +95,36 @@ void main() {
       'ts': timeStamp,
     };
 
-    List<Map<String, dynamic>> newGenGC(int count) => List<Map<String, dynamic>>.filled(
-      count,
-      <String, dynamic>{
-        'name': 'CollectNewGeneration',
-        'cat': 'GC',
-        'tid': 19695,
-        'pid': 19650,
-        'ts': 358849612473,
-        'tts': 476761,
-        'ph': 'B',
-        'args': <String, dynamic>{
-          'isolateGroupId': 'isolateGroups/10824099774666259225',
-        },
-      },
-    );
-
-    List<Map<String, dynamic>> oldGenGC(int count) => List<Map<String, dynamic>>.filled(
-      count,
-      <String, dynamic>{
-        'name': 'CollectOldGeneration',
-        'cat': 'GC',
-        'tid': 19695,
-        'pid': 19650,
-        'ts': 358849612473,
-        'tts': 476761,
-        'ph': 'B',
-        'args': <String, dynamic>{
-          'isolateGroupId': 'isolateGroups/10824099774666259225',
-        },
-      },
-    );
+    List<Map<String, dynamic>> _genGC(String name, int count, int startTime, int timeDiff) {
+      int ts = startTime;
+      bool begin = true;
+      final List<Map<String, dynamic>> ret = <Map<String, dynamic>>[];
+      for (int i = 0; i < count; i++) {
+        ret.add(<String, dynamic>{
+          'name': name,
+          'cat': 'GC',
+          'tid': 19695,
+          'pid': 19650,
+          'ts': ts,
+          'tts': ts,
+          'ph': begin ? 'B' : 'E',
+          'args': <String, dynamic>{
+            'isolateGroupId': 'isolateGroups/10824099774666259225',
+          },
+        });
+        ts = ts + timeDiff;
+        begin = !begin;
+      }
+      return ret;
+    }
+
+    List<Map<String, dynamic>> newGenGC(int count, int startTime, int timeDiff) {
+      return _genGC('CollectNewGeneration', count, startTime, timeDiff);
+    }
+
+    List<Map<String, dynamic>> oldGenGC(int count, int startTime, int timeDiff) {
+      return _genGC('CollectOldGeneration', count, startTime, timeDiff);
+    }
 
     List<Map<String, dynamic>> rasterizeTimeSequenceInMillis(List<int> sequence) {
       final List<Map<String, dynamic>> result = <Map<String, dynamic>>[];
@@ -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,
         });
       });
     });