From bc0d35c34e2065fd520f8b0bcd959af86affc20a Mon Sep 17 00:00:00 2001 From: Francisco Magdaleno Date: Fri, 27 Dec 2019 11:15:48 -0800 Subject: [PATCH] Reland "fix duration event of timeline summary (#47742)" (#47889) This reverts commit 50d421224d6b4e48589525be5d9eb036fa20a5c8. --- .../lib/src/driver/timeline_summary.dart | 47 +++------- .../test/src/timeline_summary_test.dart | 85 ++++++++++++++----- 2 files changed, 78 insertions(+), 54 deletions(-) diff --git a/packages/flutter_driver/lib/src/driver/timeline_summary.dart b/packages/flutter_driver/lib/src/driver/timeline_summary.dart index 9574b71f0ef..e7bedb9f6b3 100644 --- a/packages/flutter_driver/lib/src/driver/timeline_summary.dart +++ b/packages/flutter_driver/lib/src/driver/timeline_summary.dart @@ -57,27 +57,27 @@ class TimelineSummary { /// /// Returns null if no frames were recorded. double computeAverageFrameRasterizerTimeMillis() { - return _averageInMillis(_extractDuration(_extractGpuRasterizerDrawEvents())); + return _averageInMillis(_extractGpuRasterizerDrawDurations()); } /// The longest frame rasterization time in milliseconds. /// /// Returns null if no frames were recorded. double computeWorstFrameRasterizerTimeMillis() { - return _maxInMillis(_extractDuration(_extractGpuRasterizerDrawEvents())); + return _maxInMillis(_extractGpuRasterizerDrawDurations()); } /// The [p]-th percentile frame rasterization time in milliseconds. /// /// Returns null if no frames were recorded. double computePercentileFrameRasterizerTimeMillis(double p) { - return _percentileInMillis(_extractDuration(_extractGpuRasterizerDrawEvents()), p); + return _percentileInMillis(_extractGpuRasterizerDrawDurations(), p); } /// The number of frames that missed the [kBuildBudget] on the GPU and /// therefore are in the danger of missing frames. - int computeMissedFrameRasterizerBudgetCount([ Duration frameBuildBudget = kBuildBudget ]) => _extractGpuRasterizerDrawEvents() - .where((TimedEvent event) => event.duration > kBuildBudget) + int computeMissedFrameRasterizerBudgetCount([ Duration frameBuildBudget = kBuildBudget ]) => _extractGpuRasterizerDrawDurations() + .where((Duration duration) => duration > kBuildBudget) .length; /// The total number of frames recorded in the timeline. @@ -100,8 +100,8 @@ class TimelineSummary { 'frame_build_times': _extractFrameDurations() .map((Duration duration) => duration.inMicroseconds) .toList(), - 'frame_rasterizer_times': _extractGpuRasterizerDrawEvents() - .map((TimedEvent event) => event.duration.inMicroseconds) + 'frame_rasterizer_times': _extractGpuRasterizerDrawDurations() + .map((Duration duration) => duration.inMicroseconds) .toList(), }; } @@ -142,15 +142,11 @@ class TimelineSummary { .toList(); } - List _extractDurations(String name) { - return _extractNamedEvents(name).map((TimelineEvent event) => event.duration).toList(); - } - - /// Extracts timed events that are reported as a pair of begin/end events. + /// Extracts Duration list that are reported as a pair of begin/end events. /// /// See: https://docs.google.com/document/d/1CvAClvFfyA5R-PhYUmn5OOQtYMH4h6I0nSsKchNAySU - List _extractBeginEndEvents(String name) { - final List result = []; + List _extractBeginEndEvents(String name) { + final List result = []; // Timeline does not guarantee that the first event is the "begin" event. final Iterator events = _extractNamedEvents(name) @@ -159,10 +155,7 @@ class TimelineSummary { final TimelineEvent beginEvent = events.current; if (events.moveNext()) { final TimelineEvent endEvent = events.current; - result.add(TimedEvent( - beginEvent.timestampMicros, - endEvent.timestampMicros, - )); + result.add(Duration(microseconds: endEvent.timestampMicros - beginEvent.timestampMicros)); } } @@ -194,21 +187,7 @@ class TimelineSummary { .reduce(math.max); } - List _extractGpuRasterizerDrawEvents() => _extractBeginEndEvents('GPURasterizer::Draw'); + List _extractGpuRasterizerDrawDurations() => _extractBeginEndEvents('GPURasterizer::Draw'); - List _extractFrameDurations() => _extractDurations('Frame'); - - Iterable _extractDuration(Iterable events) { - return events.map((TimedEvent e) => e.duration); - } -} - -/// Timing information about an event that happened in the event loop. -class TimedEvent { - /// Creates a timed event given begin and end timestamps in microseconds. - TimedEvent(int beginTimeMicros, int endTimeMicros) - : duration = Duration(microseconds: endTimeMicros - beginTimeMicros); - - /// The duration of the event. - final Duration duration; + List _extractFrameDurations() => _extractBeginEndEvents('Frame'); } diff --git a/packages/flutter_driver/test/src/timeline_summary_test.dart b/packages/flutter_driver/test/src/timeline_summary_test.dart index ad2588b5b87..92afd8011d5 100644 --- a/packages/flutter_driver/test/src/timeline_summary_test.dart +++ b/packages/flutter_driver/test/src/timeline_summary_test.dart @@ -20,11 +20,16 @@ void main() { })); } - Map build(int timeStamp, int duration) => { + Map frameBegin(int timeStamp) => { 'name': 'Frame', - 'ph': 'X', + 'ph': 'B', + 'ts': timeStamp, + }; + + Map frameEnd(int timeStamp) => { + 'name': 'Frame', + 'ph': 'E', 'ts': timeStamp, - 'dur': duration, }; Map begin(int timeStamp) => { @@ -54,8 +59,8 @@ void main() { test('counts frames', () { expect( summarize(>[ - build(1000, 1000), - build(3000, 2000), + frameBegin(1000), frameEnd(2000), + frameBegin(3000), frameEnd(5000), ]).countFrames(), 2, ); @@ -73,12 +78,32 @@ void main() { test('computes average frame build time in milliseconds', () { expect( summarize(>[ - build(1000, 1000), - build(3000, 2000), + frameBegin(1000), frameEnd(2000), + frameBegin(3000), frameEnd(5000), ]).computeAverageFrameBuildTimeMillis(), 1.5, ); }); + + test('skips leading "end" events', () { + expect( + summarize(>[ + frameEnd(1000), + frameBegin(2000), frameEnd(4000), + ]).computeAverageFrameBuildTimeMillis(), + 2.0, + ); + }); + + test('skips trailing "begin" events', () { + expect( + summarize(>[ + frameBegin(2000), frameEnd(4000), + frameBegin(5000), + ]).computeAverageFrameBuildTimeMillis(), + 2.0, + ); + }); }); group('worst_frame_build_time_millis', () { @@ -92,15 +117,35 @@ void main() { test('computes worst frame build time in milliseconds', () { expect( summarize(>[ - build(1000, 1000), - build(3000, 2000), + frameBegin(1000), frameEnd(2000), + frameBegin(3000), frameEnd(5000), ]).computeWorstFrameBuildTimeMillis(), 2.0, ); expect( summarize(>[ - build(3000, 2000), - build(1000, 1000), + frameBegin(3000), frameEnd(5000), + frameBegin(1000), frameEnd(2000), + ]).computeWorstFrameBuildTimeMillis(), + 2.0, + ); + }); + + test('skips leading "end" events', () { + expect( + summarize(>[ + frameEnd(1000), + frameBegin(2000), frameEnd(4000), + ]).computeWorstFrameBuildTimeMillis(), + 2.0, + ); + }); + + test('skips trailing "begin" events', () { + expect( + summarize(>[ + frameBegin(2000), frameEnd(4000), + frameBegin(5000), ]).computeWorstFrameBuildTimeMillis(), 2.0, ); @@ -110,9 +155,9 @@ void main() { group('computeMissedFrameBuildBudgetCount', () { test('computes the number of missed build budgets', () { final TimelineSummary summary = summarize(>[ - build(1000, 17000), - build(19000, 9000), - build(29000, 18000), + frameBegin(1000), frameEnd(18000), + frameBegin(19000), frameEnd(28000), + frameBegin(29000), frameEnd(47000), ]); expect(summary.countFrames(), 3); @@ -267,9 +312,9 @@ void main() { begin(1000), end(19000), begin(19000), end(29000), begin(29000), end(49000), - build(1000, 17000), - build(19000, 9000), - build(29000, 19000), + frameBegin(1000), frameEnd(18000), + frameBegin(19000), frameEnd(28000), + frameBegin(29000), frameEnd(48000), ]).summaryJson, { 'average_frame_build_time_millis': 15.0, @@ -317,9 +362,9 @@ void main() { begin(1000), end(19000), begin(19000), end(29000), begin(29000), end(49000), - build(1000, 17000), - build(19000, 9000), - build(29000, 19000), + frameBegin(1000), frameEnd(18000), + frameBegin(19000), frameEnd(28000), + frameBegin(29000), frameEnd(48000), ]).writeSummaryToFile('test', destinationDirectory: tempDir.path); final String written = await fs.file(path.join(tempDir.path, 'test.timeline_summary.json')).readAsString();