fix frame info extraction logic; track frames in gallery test (#6505)

dev/devicelab/lib/tasks/gallery.dart

@@ -52,11 +52,22 @@ class GalleryTransitionTest {
     Map<String, dynamic> original = JSON.decode(file(
             '${galleryDirectory.path}/build/transition_durations.timeline.json')
         .readAsStringSync());
-    Map<String, dynamic> clean = new Map<String, dynamic>.fromIterable(
+    Map<String, dynamic> transitions = new Map<String, dynamic>.fromIterable(
         original.keys,
         key: (String key) => key.replaceAll('/', ''),
         value: (String key) => original[key]);
 
-    return new TaskResult.success(clean);
+    Map<String, dynamic> summary = JSON.decode(file('${galleryDirectory.path}/build/transitions.timeline_summary.json').readAsStringSync());
+
+    Map<String, dynamic> data = <String, dynamic>{
+      'transitions': transitions,
+    };
+    data.addAll(summary);
+
+    return new TaskResult.success(data, benchmarkScoreKeys: <String>[
+      'average_frame_build_time_millis',
+      'worst_frame_build_time_millis',
+      'missed_frame_build_budget_count',
+    ]);
   }
 }

dev/devicelab/lib/tasks/perf_tests.dart

@@ -108,6 +108,14 @@ class PerfTest {
         deviceId,
       ]);
       Map<String, dynamic> data = JSON.decode(file('$testDirectory/build/$timelineFileName.timeline_summary.json').readAsStringSync());
+
+      if (data['frame_count'] < 5) {
+        return new TaskResult.failure(
+          'Timeline contains too few frames: ${data['frame_count']}. Possibly '
+          'trace events are not being captured.',
+        );
+      }
+
       return new TaskResult.success(data, benchmarkScoreKeys: <String>[
         'average_frame_build_time_millis',
         'worst_frame_build_time_millis',

examples/flutter_gallery/test_driver/transitions_perf_test.dart

@@ -138,6 +138,9 @@ void main() {
       // 'Start Transition' event when a demo is launched (see GalleryItem).
       saveDurationsHistogram(timeline.json['traceEvents']);
 
+      TimelineSummary summary = new TimelineSummary.summarize(timeline);
+      summary.writeSummaryToFile('transitions');
+
     }, timeout: new Timeout(new Duration(minutes: 5)));
   });
 }

packages/flutter_driver/lib/src/timeline_summary.dart

@@ -33,7 +33,7 @@ class TimelineSummary {
     int totalBuildTimeMicros = 0;
     int frameCount = 0;
 
-    for (TimedEvent event in _extractBeginFrameEvents()) {
+    for (TimedEvent event in _extractFrameEvents()) {
       frameCount++;
       totalBuildTimeMicros += event.duration.inMicroseconds;
     }
@@ -51,7 +51,7 @@ class TimelineSummary {
     int maxBuildTimeMicros = 0;
     int frameCount = 0;
 
-    for (TimedEvent event in _extractBeginFrameEvents()) {
+    for (TimedEvent event in _extractFrameEvents()) {
       frameCount++;
       maxBuildTimeMicros = math.max(maxBuildTimeMicros, event.duration.inMicroseconds);
     }
@@ -62,13 +62,13 @@ class TimelineSummary {
   }
 
   /// The total number of frames recorded in the timeline.
-  int countFrames() => _extractBeginFrameEvents().length;
+  int countFrames() => _extractFrameEvents().length;
 
   /// The number of frames that missed the [frameBuildBudget] and therefore are
   /// in the danger of missing frames.
   ///
   /// See [kBuildBudget].
-  int computeMissedFrameBuildBudgetCount([Duration frameBuildBudget = kBuildBudget]) => _extractBeginFrameEvents()
+  int computeMissedFrameBuildBudgetCount([Duration frameBuildBudget = kBuildBudget]) => _extractFrameEvents()
     .where((TimedEvent event) => event.duration > kBuildBudget)
     .length;
 
@@ -79,7 +79,7 @@ class TimelineSummary {
       'worst_frame_build_time_millis': computeWorstFrameBuildTimeMillis(),
       'missed_frame_build_budget_count': computeMissedFrameBuildBudgetCount(),
       'frame_count': countFrames(),
-      'frame_build_times': _extractBeginFrameEvents()
+      'frame_build_times': _extractFrameEvents()
         .map((TimedEvent event) => event.duration.inMicroseconds)
         .toList()
     };
@@ -113,28 +113,22 @@ class TimelineSummary {
       .toList();
   }
 
-  /// Extracts timed events that are reported as a pair of begin/end events.
-  List<TimedEvent> _extractTimedBeginEndEvents(String name) {
-    List<TimedEvent> result = <TimedEvent>[];
-
-    // Timeline does not guarantee that the first event is the "begin" event.
-    Iterator<TimelineEvent> events = _extractNamedEvents(name)
-        .skipWhile((TimelineEvent evt) => evt.phase != 'B').iterator;
-    while(events.moveNext()) {
-      TimelineEvent beginEvent = events.current;
-      if (events.moveNext()) {
-        TimelineEvent endEvent = events.current;
-        result.add(new TimedEvent(
-          beginEvent.timestampMicros,
-          endEvent.timestampMicros
-        ));
-      }
-    }
-
-    return result;
+  /// Extracts timed events that are reported as complete ("X") timeline events.
+  ///
+  /// 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) {
+          return new TimedEvent(
+            event.timestampMicros,
+            event.timestampMicros + event.duration.inMicroseconds,
+          );
+        })
+        .toList();
   }
 
-  List<TimedEvent> _extractBeginFrameEvents() => _extractTimedBeginEndEvents('Engine::BeginFrame');
+  List<TimedEvent> _extractFrameEvents() => _extractCompleteEvents('Frame');
 }
 
 /// Timing information about an event that happened in the event loop.

packages/flutter_driver/test/src/timeline_summary_test.dart

@@ -17,20 +17,16 @@ void main() {
       }));
     }
 
-    Map<String, dynamic> begin(int timeStamp) => <String, dynamic>{
-      'name': 'Engine::BeginFrame', 'ph': 'B', 'ts': timeStamp
-    };
-
-    Map<String, dynamic> end(int timeStamp) => <String, dynamic>{
-      'name': 'Engine::BeginFrame', 'ph': 'E', 'ts': timeStamp
+    Map<String, dynamic> frame(int timeStamp, int duration) => <String, dynamic>{
+      'name': 'Frame', 'ph': 'X', 'ts': timeStamp, 'dur': duration
     };
 
     group('frame_count', () {
       test('counts frames', () {
         expect(
           summarize(<Map<String, dynamic>>[
-            begin(1000), end(2000),
-            begin(3000), end(5000),
+            frame(1000, 1000),
+            frame(3000, 2000),
           ]).countFrames(),
           2
         );
@@ -45,32 +41,12 @@ void main() {
       test('computes average frame build time in milliseconds', () {
         expect(
           summarize(<Map<String, dynamic>>[
-            begin(1000), end(2000),
-            begin(3000), end(5000),
+            frame(1000, 1000),
+            frame(3000, 2000),
           ]).computeAverageFrameBuildTimeMillis(),
           1.5
         );
       });
-
-      test('skips leading "end" events', () {
-        expect(
-          summarize(<Map<String, dynamic>>[
-            end(1000),
-            begin(2000), end(4000),
-          ]).computeAverageFrameBuildTimeMillis(),
-          2.0
-        );
-      });
-
-      test('skips trailing "begin" events', () {
-        expect(
-          summarize(<Map<String, dynamic>>[
-            begin(2000), end(4000),
-            begin(5000),
-          ]).computeAverageFrameBuildTimeMillis(),
-          2.0
-        );
-      });
     });
 
     group('worst_frame_build_time_millis', () {
@@ -81,35 +57,15 @@ void main() {
       test('computes worst frame build time in milliseconds', () {
         expect(
           summarize(<Map<String, dynamic>>[
-            begin(1000), end(2000),
-            begin(3000), end(5000),
-          ]).computeWorstFrameBuildTimeMillis(),
-          2.0
-        );
-        expect(
-          summarize(<Map<String, dynamic>>[
-            begin(3000), end(5000),
-            begin(1000), end(2000),
+            frame(1000, 1000),
+            frame(3000, 2000),
           ]).computeWorstFrameBuildTimeMillis(),
           2.0
         );
-      });
-
-      test('skips leading "end" events', () {
-        expect(
-          summarize(<Map<String, dynamic>>[
-            end(1000),
-            begin(2000), end(4000),
-          ]).computeWorstFrameBuildTimeMillis(),
-          2.0
-        );
-      });
-
-      test('skips trailing "begin" events', () {
         expect(
           summarize(<Map<String, dynamic>>[
-            begin(2000), end(4000),
-            begin(5000),
+            frame(3000, 2000),
+            frame(1000, 1000),
           ]).computeWorstFrameBuildTimeMillis(),
           2.0
         );
@@ -119,9 +75,9 @@ void main() {
     group('computeMissedFrameBuildBudgetCount', () {
       test('computes the number of missed build budgets', () {
         TimelineSummary summary = summarize(<Map<String, dynamic>>[
-          begin(1000), end(10000),
-          begin(11000), end(12000),
-          begin(13000), end(23000),
+          frame(1000, 9000),
+          frame(11000, 1000),
+          frame(13000, 10000),
         ]);
 
         expect(summary.countFrames(), 3);
@@ -133,9 +89,9 @@ void main() {
       test('computes and returns summary as JSON', () {
         expect(
           summarize(<Map<String, dynamic>>[
-            begin(1000), end(10000),
-            begin(11000), end(12000),
-            begin(13000), end(24000),
+            frame(1000, 9000),
+            frame(11000, 1000),
+            frame(13000, 11000),
           ]).summaryJson,
           <String, dynamic>{
             'average_frame_build_time_millis': 7.0,
@@ -167,9 +123,9 @@ void main() {
 
       test('writes summary to JSON file', () async {
         await summarize(<Map<String, dynamic>>[
-          begin(1000), end(10000),
-          begin(11000), end(12000),
-          begin(13000), end(24000),
+          frame(1000, 9000),
+          frame(11000, 1000),
+          frame(13000, 11000),
         ]).writeSummaryToFile('test', destinationDirectory: '/temp');
         String written =
             await fs.file('/temp/test.timeline_summary.json').readAsString();