Skip to content

[flutter_tools] Make flutter test -v print timing of different phases#108864

Merged
auto-submit[bot] merged 3 commits intoflutter:masterfrom
jensjoha:flutter_test_time_phases
Aug 18, 2022
Merged

[flutter_tools] Make flutter test -v print timing of different phases#108864
auto-submit[bot] merged 3 commits intoflutter:masterfrom
jensjoha:flutter_test_time_phases

Conversation

@jensjoha
Copy link
Contributor

@jensjoha jensjoha commented Aug 3, 2022

This PR adds timing to different phases of a flutter test run when run in verbose mode (i.e. really flutter test -v).
It is only done when run in verbose mode, and at the end of such a run something like this is printed (examples when run without and with coverage, respectively):

$ flutter test -v
[...]
04:08 +11253 ~66: All tests passed!
[...]
[   +1 ms] Runtime for phase TestRunner: Wall-clock: 0:04:10.433205; combined: 0:04:10.433270.
[        ] Runtime for phase Compile: Wall-clock: 0:02:26.767039; combined: 0:02:26.768384.
[        ] Runtime for phase Run: Wall-clock: 0:03:59.813981; combined: 0:34:41.530487.
[        ] Runtime for phase CoverageTotal: Wall-clock: 0:00:00.000000; combined: 0:00:00.000000.
[        ] Runtime for phase Coverage_collect: Wall-clock: 0:00:00.000000; combined: 0:00:00.000000.
[        ] Runtime for phase Coverage_parseJson: Wall-clock: 0:00:00.000000; combined: 0:00:00.000000.
[        ] Runtime for phase Coverage_addHitmap: Wall-clock: 0:00:00.000000; combined: 0:00:00.000000.
[        ] Runtime for phase CoverageDataCollect: Wall-clock: 0:00:00.000000; combined: 0:00:00.000000.
[        ] Runtime for phase WatcherFinishedTest: Wall-clock: 0:00:00.053933; combined: 0:00:00.055020.
[        ] "flutter test" took 251,741ms.

$ flutter test --coverage -v
[...]
10:36 +11253 ~66: All tests passed!
[...]
[        ] Runtime for phase TestRunner: Wall-clock: 0:10:38.437213; combined: 0:10:38.437255.
[        ] Runtime for phase Compile: Wall-clock: 0:03:41.295140; combined: 0:03:41.296021.
[        ] Runtime for phase Run: Wall-clock: 0:09:29.499648; combined: 0:38:39.588928.
[        ] Runtime for phase CoverageTotal: Wall-clock: 0:09:51.073961; combined: 0:51:35.341727.
[        ] Runtime for phase Coverage_collect: Wall-clock: 0:09:48.354589; combined: 0:51:03.565451.
[        ] Runtime for phase Coverage_parseJson: Wall-clock: 0:00:28.882393; combined: 0:00:28.883917.
[        ] Runtime for phase Coverage_addHitmap: Wall-clock: 0:00:02.765673; combined: 0:00:02.766548.
[        ] Runtime for phase CoverageDataCollect: Wall-clock: 0:00:00.074591; combined: 0:00:00.074591.
[        ] Runtime for phase WatcherFinishedTest: Wall-clock: 0:09:51.080064; combined: 0:51:35.401420.

This can be seen as a productization of #100751 (comment) where these timing numbers (fewer, but still) helped debug what was slow on a CI. Similarly, I've used (a non-productization version of) these numbers to uncover the speed issue fixed in #107395.

@jensjoha jensjoha requested a review from jonahwilliams August 3, 2022 08:16
@flutter-dashboard flutter-dashboard bot added the tool Affects the "flutter" command-line tool. See also t: labels. label Aug 3, 2022
@jensjoha
Copy link
Contributor Author

jensjoha commented Aug 10, 2022

Ping.

jonahwilliams
jonahwilliams suggested changes Aug 11, 2022
View reviewed changes
Copy link
Contributor

@jonahwilliams jonahwilliams left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Sorry for the delay on this review

@jensjoha jensjoha force-pushed the flutter_test_time_phases branch from b600811 to 1681680 Compare August 18, 2022 13:02
@jensjoha jensjoha requested a review from jonahwilliams August 18, 2022 13:05
jonahwilliams
jonahwilliams approved these changes Aug 18, 2022
View reviewed changes
Copy link
Contributor

@jonahwilliams jonahwilliams left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

LGTM!

@jonahwilliams jonahwilliams added the autosubmit Merge PR when tree becomes green via auto submit App label Aug 18, 2022
@auto-submit auto-submit bot merged commit 981bdf5 into flutter:master Aug 18, 2022
@jensjoha jensjoha deleted the flutter_test_time_phases branch August 19, 2022 06:28
This was referenced Aug 19, 2022
Merged
Merged
engine-flutter-autoroll added a commit to engine-flutter-autoroll/packages that referenced this pull request Aug 19, 2022
@engine-flutter-autoroll
981bdf5 [flutter_tools] Make flutter test -v print timing of differen…
af02dc7 
…t phases (flutter/flutter#108864)
engine-flutter-autoroll added a commit to engine-flutter-autoroll/plugins that referenced this pull request Aug 19, 2022
@engine-flutter-autoroll
981bdf5 [flutter_tools] Make flutter test -v print timing of differen…
a15d394 
…t phases (flutter/flutter#108864)
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Reviewers

@christopherfujino christopherfujino Awaiting requested review from christopherfujino

1 more reviewer

@jonahwilliams jonahwilliams jonahwilliams approved these changes

Reviewers whose approvals may not affect merge requirements

Assignees

No one assigned

Labels

autosubmit Merge PR when tree becomes green via auto submit App tool Affects the "flutter" command-line tool. See also t: labels.

Projects

None yet

Milestone

No milestone

Development

Successfully merging this pull request may close these issues.

2 participants

@jensjoha @jonahwilliams