Merge pull request #3058 from yjbanov/timeline-summary

[driver] utility for extracting and saving timeline summary

examples/stocks/test_driver/scroll_perf_test.dart

@@ -21,7 +21,7 @@ void main() {
     });
 
     test('measure', () async {
-      Map<String, dynamic> profileJson = await driver.traceAction(() async {
+      Map<String, dynamic> timeline = await driver.traceAction(() async {
         // Find the scrollable stock list
         ObjectRef stockList = await driver.findByValueKey('stock-list');
         expect(stockList, isNotNull);
@@ -39,10 +39,10 @@ void main() {
         }
       });
 
-      // Usually the profile is saved to a file and then analyzed using
-      // chrom://tracing or a script. Both are out of scope for this little
-      // test, so all we do is check that we received something.
-      expect(profileJson, isNotNull);
+      expect(timeline, isNotNull);
+      TimelineSummary summary = summarizeTimeline(timeline);
+      summary.writeSummaryToFile('stocks_scroll_perf', pretty: true);
+      summary.writeTimelineToFile('stocks_scroll_perf', pretty: true);
     });
   });
 }

packages/flutter_driver/lib/flutter_driver.dart

@@ -36,3 +36,8 @@ export 'src/message.dart' show
   ObjectRef,
   CommandWithTarget,
   Result;
+
+export 'src/timeline_summary.dart' show
+  summarizeTimeline,
+  EventTrace,
+  TimelineSummary;

packages/flutter_driver/lib/src/common.dart

@@ -0,0 +1,22 @@
+// Copyright 2016 The Chromium 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 'package:file/file.dart';
+import 'package:file/io.dart';
+
+/// The file system implementation used by this library.
+///
+/// See [useMemoryFileSystemForTesting] and [restoreFileSystem].
+FileSystem fs = new LocalFileSystem();
+
+/// Overrides the file system so it can be tested without hitting the hard
+/// drive.
+void useMemoryFileSystemForTesting() {
+  fs = new MemoryFileSystem();
+}
+
+/// Restores the file system to the default local file system implementation.
+void restoreFileSystem() {
+  fs = new LocalFileSystem();
+}

packages/flutter_driver/lib/src/timeline_summary.dart

@@ -0,0 +1,132 @@
+// Copyright 2016 The Chromium 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 'dart:async';
+import 'dart:convert' show JSON, JsonEncoder;
+
+import 'package:file/file.dart';
+import 'package:path/path.dart' as path;
+
+import 'common.dart';
+
+const String _kDefaultDirectory = 'build';
+final JsonEncoder _prettyEncoder = new JsonEncoder.withIndent('  ');
+
+/// The maximum amount of time considered safe to spend for a frame's build
+/// phase. Anything past that is in the danger of missing the frame as 60FPS.
+const Duration kBuildBudget = const Duration(milliseconds: 8);
+
+/// Extracts statistics from the event loop timeline.
+TimelineSummary summarizeTimeline(Map<String, dynamic> timeline) {
+  return new TimelineSummary(timeline);
+}
+
+class TimelineSummary {
+  TimelineSummary(this._timeline);
+
+  final Map<String, dynamic> _timeline;
+
+  /// Average amount of time spent per frame in the framework building widgets,
+  /// updating layout, painting and compositing.
+  double computeAverageFrameBuildTimeMillis() {
+    int totalBuildTimeMicros = 0;
+    int frameCount = 0;
+
+    for (TimedEvent event in _extractBeginFrameEvents()) {
+      frameCount++;
+      totalBuildTimeMicros += event.duration.inMicroseconds;
+    }
+
+    return frameCount > 0
+      ? (totalBuildTimeMicros / frameCount) / 1000
+      : null;
+  }
+
+  /// The total number of frames recorded in the timeline.
+  int countFrames() => _extractBeginFrameEvents().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()
+    .where((TimedEvent event) => event.duration > kBuildBudget)
+    .length;
+
+  /// Encodes this summary as JSON.
+  Map<String, dynamic> get summaryJson {
+    return <String, dynamic> {
+      'average_frame_build_time_millis': computeAverageFrameBuildTimeMillis(),
+      'missed_frame_build_budget_count': computeMissedFrameBuildBudgetCount(),
+      'frame_count': countFrames(),
+    };
+  }
+
+  /// Writes all of the recorded timeline data to a file.
+  Future<Null> writeTimelineToFile(String traceName,
+      {String destinationDirectory: _kDefaultDirectory, bool pretty: false}) async {
+    await fs.directory(destinationDirectory).create(recursive: true);
+    File file = fs.file(path.join(destinationDirectory, '$traceName.timeline.json'));
+    await file.writeAsString(_encodeJson(_timeline, pretty));
+  }
+
+  /// Writes [summaryJson] to a file.
+  Future<Null> writeSummaryToFile(String traceName,
+      {String destinationDirectory: _kDefaultDirectory, bool pretty: false}) async {
+    await fs.directory(destinationDirectory).create(recursive: true);
+    File file = fs.file(path.join(destinationDirectory, '$traceName.timeline_summary.json'));
+    await file.writeAsString(_encodeJson(summaryJson, pretty));
+  }
+
+  String _encodeJson(dynamic json, bool pretty) {
+    return pretty
+      ? _prettyEncoder.convert(json)
+      : JSON.encode(json);
+  }
+
+  List<Map<String, dynamic>> get _traceEvents => _timeline['traceEvents'];
+
+  List<Map<String, dynamic>> _extractNamedEvents(String name) {
+    return _traceEvents
+      .where((Map<String, dynamic> event) => event['name'] == name)
+      .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<Map<String, dynamic>> events = _extractNamedEvents(name)
+        .skipWhile((Map<String, dynamic> evt) => evt['ph'] != 'B').iterator;
+    while(events.moveNext()) {
+      Map<String, dynamic> beginEvent = events.current;
+      if (events.moveNext()) {
+        Map<String, dynamic> endEvent = events.current;
+        result.add(new TimedEvent(beginEvent['ts'], endEvent['ts']));
+      }
+    }
+
+    return result;
+  }
+
+  List<TimedEvent> _extractBeginFrameEvents() => _extractTimedBeginEndEvents('Engine::BeginFrame');
+}
+
+/// Timing information about an event that happened in the event loop.
+class TimedEvent {
+  /// The timestamp when the event began.
+  final int beginTimeMicros;
+
+  /// The timestamp when the event ended.
+  final int endTimeMicros;
+
+  /// The duration of the event.
+  final Duration duration;
+
+  TimedEvent(int beginTimeMicros, int endTimeMicros)
+    : this.beginTimeMicros = beginTimeMicros,
+      this.endTimeMicros = endTimeMicros,
+      this.duration = new Duration(microseconds: endTimeMicros - beginTimeMicros);
+}

packages/flutter_driver/pubspec.yaml

@@ -8,8 +8,10 @@ environment:
   sdk: '>=1.12.0 <2.0.0'
 
 dependencies:
+  file: ^0.1.0
   json_rpc_2: any
   matcher: '>=0.12.0 <1.0.0'
+  path: ^1.3.0
   vm_service_client: '>=0.1.2 <1.0.0'
   flutter:
     path: '../flutter'

packages/flutter_driver/test/all.dart

@@ -3,7 +3,7 @@
 // found in the LICENSE file.
 
 import 'flutter_driver_test.dart' as flutter_driver_test;
-import 'retry_test.dart' as retry_test;
+import 'src/retry_test.dart' as retry_test;
 
 void main() {
   flutter_driver_test.main();

packages/flutter_driver/test/src/timeline_summary_test.dart

@@ -0,0 +1,139 @@
+// Copyright 2016 The Chromium 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 'dart:convert' show JSON;
+
+import 'package:test/test.dart';
+import 'package:flutter_driver/src/common.dart';
+import 'package:flutter_driver/src/timeline_summary.dart';
+
+void main() {
+  group('TimelineSummary', () {
+
+    TimelineSummary summarize(List<Map<String, dynamic>> testEvents) {
+      return summarizeTimeline(<String, dynamic>{
+        'traceEvents': testEvents,
+      });
+    }
+
+    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
+    };
+
+    group('frame_count', () {
+      test('counts frames', () {
+        expect(
+          summarize([
+            begin(1000), end(2000),
+            begin(3000), end(5000),
+          ]).countFrames(),
+          2
+        );
+      });
+    });
+
+    group('average_frame_build_time_millis', () {
+      test('returns null when there is no data', () {
+        expect(summarize([]).computeAverageFrameBuildTimeMillis(), isNull);
+      });
+
+      test('computes average frame build time in milliseconds', () {
+        expect(
+          summarize([
+            begin(1000), end(2000),
+            begin(3000), end(5000),
+          ]).computeAverageFrameBuildTimeMillis(),
+          1.5
+        );
+      });
+
+      test('skips leading "end" events', () {
+        expect(
+          summarize([
+            end(1000),
+            begin(2000), end(4000),
+          ]).computeAverageFrameBuildTimeMillis(),
+          2
+        );
+      });
+
+      test('skips trailing "begin" events', () {
+        expect(
+          summarize([
+            begin(2000), end(4000),
+            begin(5000),
+          ]).computeAverageFrameBuildTimeMillis(),
+          2
+        );
+      });
+    });
+
+    group('computeMissedFrameBuildBudgetCount', () {
+      test('computes the number of missed build budgets', () {
+        TimelineSummary summary = summarize([
+          begin(1000), end(10000),
+          begin(11000), end(12000),
+          begin(13000), end(23000),
+        ]);
+
+        expect(summary.countFrames(), 3);
+        expect(summary.computeMissedFrameBuildBudgetCount(), 2);
+      });
+    });
+
+    group('summaryJson', () {
+      test('computes and returns summary as JSON', () {
+        expect(
+          summarize([
+            begin(1000), end(10000),
+            begin(11000), end(12000),
+            begin(13000), end(24000),
+          ]).summaryJson,
+          {
+            'average_frame_build_time_millis': 7.0,
+            'missed_frame_build_budget_count': 2,
+            'frame_count': 3,
+          }
+        );
+      });
+    });
+
+    group('writeTimelineToFile', () {
+      setUp(() {
+        useMemoryFileSystemForTesting();
+      });
+
+      tearDown(() {
+        restoreFileSystem();
+      });
+
+      test('writes timeline to JSON file', () async {
+        await summarize([{'foo': 'bar'}])
+          .writeTimelineToFile('test', destinationDirectory: '/temp');
+        String written =
+            await fs.file('/temp/test.timeline.json').readAsString();
+        expect(written, '{"traceEvents":[{"foo":"bar"}]}');
+      });
+
+      test('writes summary to JSON file', () async {
+        await summarize([
+          begin(1000), end(10000),
+          begin(11000), end(12000),
+          begin(13000), end(24000),
+        ]).writeSummaryToFile('test', destinationDirectory: '/temp');
+        String written =
+            await fs.file('/temp/test.timeline_summary.json').readAsString();
+        expect(JSON.decode(written), {
+          'average_frame_build_time_millis': 7.0,
+          'missed_frame_build_budget_count': 2,
+          'frame_count': 3,
+        });
+      });
+    });
+  });
+}