From be86554479ca9eae6bca3335ae2fa4cc8fc9a8ba Mon Sep 17 00:00:00 2001 From: Adam Barth Date: Mon, 13 Feb 2017 16:07:07 -0800 Subject: [PATCH] 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 | 12 ++++ .../lib/src/timeline_summary.dart | 55 +++++++++---------- .../test/src/timeline_summary_test.dart | 2 +- .../test/src/timeline_test.dart | 3 + 4 files changed, 41 insertions(+), 31 deletions(-) diff --git a/packages/flutter_driver/lib/src/timeline.dart b/packages/flutter_driver/lib/src/timeline.dart index 32a63ee631..bb1d063d3e 100644 --- a/packages/flutter_driver/lib/src/timeline.dart +++ b/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. diff --git a/packages/flutter_driver/lib/src/timeline_summary.dart b/packages/flutter_driver/lib/src/timeline_summary.dart index 580f1c294c..5706fe2b83 100644 --- a/packages/flutter_driver/lib/src/timeline_summary.dart +++ b/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() - .where((TimedEvent event) => event.duration > kBuildBudget) + int computeMissedFrameBuildBudgetCount([Duration frameBuildBudget = kBuildBudget]) => _extractFrameThreadDurations() + .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 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() - .map((TimedEvent event) => event.duration.inMicroseconds) + 'frame_build_times': _extractFrameThreadDurations() + .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. - /// - /// See: https://docs.google.com/document/d/1CvAClvFfyA5R-PhYUmn5OOQtYMH4h6I0nSsKchNAySU - List _extractCompleteEvents(String name) { + List _extractThreadDurations(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(); + .map((TimelineEvent event) => event.threadDuration).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 events) { - if (events.length == 0) + double _averageInMillis(Iterable durations) { + if (durations.isEmpty) return null; - int total = events.fold(0, (int t, TimedEvent e) => t + e.duration.inMilliseconds); - return total / events.length; + int total = durations.fold(0, (int t, Duration duration) => t + duration.inMilliseconds); + return total / durations.length; } - double _maxDurationInMillis(List events) { - if (events.length == 0) + double _maxInMillis(Iterable durations) { + if (durations.isEmpty) return null; - return events - .map((TimedEvent e) => e.duration.inMilliseconds.toDouble()) + return durations + .map((Duration duration) => duration.inMilliseconds.toDouble()) .reduce((double a, double b) => math.max(a, b)); } - List _extractFrameEvents() => _extractCompleteEvents('Frame'); List _extractGpuRasterizerDrawEvents() => _extractBeginEndEvents('GPURasterizer::Draw'); + + List _extractFrameThreadDurations() => _extractThreadDurations('Frame'); + + Iterable _extractDuration(Iterable events) { + return events.map((TimedEvent e) => e.duration); + } } /// Timing information about an event that happened in the event loop. diff --git a/packages/flutter_driver/test/src/timeline_summary_test.dart b/packages/flutter_driver/test/src/timeline_summary_test.dart index 0540bd1e87..1701db3ad2 100644 --- a/packages/flutter_driver/test/src/timeline_summary_test.dart +++ b/packages/flutter_driver/test/src/timeline_summary_test.dart @@ -20,7 +20,7 @@ void main() { } Map build(int timeStamp, int duration) => { - 'name': 'Frame', 'ph': 'X', 'ts': timeStamp, 'dur': duration + 'name': 'Frame', 'ph': 'X', 'ts': timeStamp, 'tdur': duration }; Map begin(int timeStamp) => { diff --git a/packages/flutter_driver/test/src/timeline_test.dart b/packages/flutter_driver/test/src/timeline_test.dart index 6c469f72ac..3e7211ea3d 100644 --- a/packages/flutter_driver/test/src/timeline_test.dart +++ b/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': { @@ -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, { '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);