Switch benchmarks to thread duration (#8113)

For measuring the Dart thread, we care about thread duration (tdur) rather than
wall duration (dur) because we don't want to count the time when the Dart
thread is descheduled (e.g., in preference to the raster thread).

Prior to this change, these benchmarks were mostly measuring whether the OS
decided to finish the Dart thread's time slice or hand over the CPU to the
raster thread to complete the visual part of the frame. Now we actually measure
the work done on the Dart thread.

packages/flutter_driver/lib/src/timeline.dart

@@ -37,6 +37,9 @@ class TimelineEvent {
       json['dur'] != null
         ? new Duration(microseconds: json['dur'])
         : null,
+      json['tdur'] != null
+        ? new Duration(microseconds: json['tdur'])
+        : null,
       json['ts'],
       json['tts'],
       json['args']
@@ -51,6 +54,7 @@ class TimelineEvent {
     this.processId,
     this.threadId,
     this.duration,
+    this.threadDuration,
     this.timestampMicros,
     this.threadTimestampMicros,
     this.arguments
@@ -93,6 +97,14 @@ class TimelineEvent {
   /// Corresponds to the "dur" field in the JSON event.
   final Duration duration;
 
+  /// The thread duration of the event.
+  ///
+  /// Note, some events are reported with duration. Others are reported as a
+  /// pair of begin/end events.
+  ///
+  /// Corresponds to the "tdur" field in the JSON event.
+  final Duration threadDuration;
+
   /// Time passed since tracing was enabled, in microseconds.
   ///
   /// Corresponds to the "ts" field in the JSON event.

packages/flutter_driver/lib/src/timeline_summary.dart

@@ -30,34 +30,34 @@ class TimelineSummary {
   ///
   /// Returns `null` if no frames were recorded.
   double computeAverageFrameBuildTimeMillis() {
-    return _averageDurationInMillis(_extractFrameEvents());
+    return _averageInMillis(_extractFrameThreadDurations());
   }
 
   /// The longest frame build time in milliseconds.
   ///
   /// Returns `null` if no frames were recorded.
   double computeWorstFrameBuildTimeMillis() {
-    return _maxDurationInMillis(_extractFrameEvents());
+    return _maxInMillis(_extractFrameThreadDurations());
   }
 
   /// The number of frames that missed the [kBuildBudget] and therefore are
   /// in the danger of missing frames.
-  int computeMissedFrameBuildBudgetCount([Duration frameBuildBudget = kBuildBudget]) => _extractFrameEvents()
+  int computeMissedFrameBuildBudgetCount([Duration frameBuildBudget = kBuildBudget]) => _extractFrameThreadDurations()
-    .where((TimedEvent event) => event.duration > kBuildBudget)
+    .where((Duration duration) => duration > kBuildBudget)
     .length;
 
   /// Average amount of time spent per frame in the GPU rasterizer.
   ///
   /// Returns `null` if no frames were recorded.
   double computeAverageFrameRasterizerTimeMillis() {
-    return _averageDurationInMillis(_extractGpuRasterizerDrawEvents());
+    return _averageInMillis(_extractDuration(_extractGpuRasterizerDrawEvents()));
   }
 
   /// The longest frame rasterization time in milliseconds.
   ///
   /// Returns `null` if no frames were recorded.
   double computeWorstFrameRasterizerTimeMillis() {
-    return _maxDurationInMillis(_extractGpuRasterizerDrawEvents());
+    return _maxInMillis(_extractDuration(_extractGpuRasterizerDrawEvents()));
   }
 
   /// The number of frames that missed the [kBuildBudget] on the GPU and
@@ -67,7 +67,7 @@ class TimelineSummary {
       .length;
 
   /// The total number of frames recorded in the timeline.
-  int countFrames() => _extractFrameEvents().length;
+  int countFrames() => _extractFrameThreadDurations().length;
 
   /// Encodes this summary as JSON.
   Map<String, dynamic> get summaryJson {
@@ -79,8 +79,8 @@ class TimelineSummary {
       'worst_frame_rasterizer_time_millis': computeWorstFrameRasterizerTimeMillis(),
       'missed_frame_rasterizer_budget_count': computeMissedFrameRasterizerBudgetCount(),
       'frame_count': countFrames(),
-      'frame_build_times': _extractFrameEvents()
+      'frame_build_times': _extractFrameThreadDurations()
-        .map((TimedEvent event) => event.duration.inMicroseconds)
+        .map((Duration duration) => duration.inMicroseconds)
         .toList(),
       'frame_rasterizer_times': _extractGpuRasterizerDrawEvents()
           .map((TimedEvent event) => event.duration.inMicroseconds)
@@ -118,19 +118,9 @@ class TimelineSummary {
       .toList();
   }
 
-  /// Extracts timed events that are reported as complete ("X") timeline events.
+  List<Duration> _extractThreadDurations(String name) {
-  ///
-  /// See: https://docs.google.com/document/d/1CvAClvFfyA5R-PhYUmn5OOQtYMH4h6I0nSsKchNAySU
-  List<TimedEvent> _extractCompleteEvents(String name) {
     return _extractNamedEvents(name)
-        .where((TimelineEvent event) => event.phase == 'X')
+        .map((TimelineEvent event) => event.threadDuration).toList();
-        .map((TimelineEvent event) {
-          return new TimedEvent(
-            event.timestampMicros,
-            event.timestampMicros + event.duration.inMicroseconds,
-          );
-        })
-        .toList();
   }
 
   /// Extracts timed events that are reported as a pair of begin/end events.
@@ -156,25 +146,30 @@ class TimelineSummary {
     return result;
   }
 
-  double _averageDurationInMillis(List<TimedEvent> events) {
+  double _averageInMillis(Iterable<Duration> durations) {
-    if (events.length == 0)
+    if (durations.isEmpty)
       return null;
 
-    int total = events.fold<int>(0, (int t, TimedEvent e) => t + e.duration.inMilliseconds);
+    int total = durations.fold<int>(0, (int t, Duration duration) => t + duration.inMilliseconds);
-    return total / events.length;
+    return total / durations.length;
   }
 
-  double _maxDurationInMillis(List<TimedEvent> events) {
+  double _maxInMillis(Iterable<Duration> durations) {
-    if (events.length == 0)
+    if (durations.isEmpty)
       return null;
 
-    return events
+    return durations
-        .map<double>((TimedEvent e) => e.duration.inMilliseconds.toDouble())
+        .map<double>((Duration duration) => duration.inMilliseconds.toDouble())
         .reduce((double a, double b) => math.max(a, b));
   }
 
-  List<TimedEvent> _extractFrameEvents() => _extractCompleteEvents('Frame');
   List<TimedEvent> _extractGpuRasterizerDrawEvents() => _extractBeginEndEvents('GPURasterizer::Draw');
+
+  List<Duration> _extractFrameThreadDurations() => _extractThreadDurations('Frame');
+
+  Iterable<Duration> _extractDuration(Iterable<TimedEvent> events) {
+    return events.map((TimedEvent e) => e.duration);
+  }
 }
 
 /// Timing information about an event that happened in the event loop.

packages/flutter_driver/test/src/timeline_summary_test.dart

@@ -20,7 +20,7 @@ void main() {
     }
 
     Map<String, dynamic> build(int timeStamp, int duration) => <String, dynamic>{
-      'name': 'Frame', 'ph': 'X', 'ts': timeStamp, 'dur': duration
+      'name': 'Frame', 'ph': 'X', 'ts': timeStamp, 'tdur': duration
     };
 
     Map<String, dynamic> begin(int timeStamp) => <String, dynamic>{

packages/flutter_driver/test/src/timeline_test.dart

@@ -17,6 +17,7 @@ void main() {
             'pid': 123,
             'tid': 234,
             'dur': 345,
+            'tdur': 245,
             'ts': 456,
             'tts': 567,
             'args': <String, dynamic>{
@@ -37,6 +38,7 @@ void main() {
       expect(e1.processId, 123);
       expect(e1.threadId, 234);
       expect(e1.duration, const Duration(microseconds: 345));
+      expect(e1.threadDuration, const Duration(microseconds: 245));
       expect(e1.timestampMicros, 456);
       expect(e1.threadTimestampMicros, 567);
       expect(e1.arguments, <String, dynamic>{ 'arg1': true });
@@ -48,6 +50,7 @@ void main() {
       expect(e2.processId, isNull);
       expect(e2.threadId, isNull);
       expect(e2.duration, isNull);
+      expect(e2.threadDuration, isNull);
       expect(e2.timestampMicros, isNull);
       expect(e2.threadTimestampMicros, isNull);
       expect(e2.arguments, isNull);