Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Show timing and allocations for tests #1787

Merged
merged 8 commits into from
Mar 5, 2022
Merged

Show timing and allocations for tests #1787

merged 8 commits into from
Mar 5, 2022

Conversation

rikhuijzer
Copy link
Contributor

@rikhuijzer rikhuijzer commented Mar 3, 2022

Given that we already run a lot of tests on a lot of systems, it makes sense to collect some allocations and time information. This PR collects the information during running the tests into an ordered dictionary and once the test is done, it will convert that into a DataFrame. Next, this can be pretty printed at the end of the tests and in a separate step in the GitHub Action. That separate Actions step makes it easy to see the output, that is, without having to scroll through all the logs.

This PR will also make detecting performance regressions easier when working on upstream packages with integration tests such as Libtask.jl.

In response to a suggestion by David in another place about using BenchmarkCI.jl. I've tried to apply it here too, but didn't see how that package can be based on tests. They only mention PkgBenchmark.jl which is based on putting things inside benchmark/ (https://juliaci.github.io/PkgBenchmark.jl/stable/define_benchmarks/). Also, the code that I've added here isn't that much and can now easily be tweaked.

Copy link
Member

@devmotion devmotion left a comment

Choose a reason for hiding this comment

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

Could we maybe use something less intrusive, without all the special commands? I think this leads to a quite unidiomatic and surprising test structure. Maybe we could use https://github.com/KristofferC/TimerOutputs.jl or something similar?

It is also problematic in general to write into the package directory, it might be read-only (IIRC there were also discussions about possibly making them immutable at some point in the future).

@rikhuijzer
Copy link
Contributor Author

rikhuijzer commented Mar 4, 2022

This is now the output for DynamicHMC-CI / test (1, ubuntu-latest, x64):

──────────────────────────────────────────────────────────────────
                                        Time          Allocations  
                                  ───────────────   ───────────────
          Total measured:              2066s             283GiB    

 Section                  ncalls     time    %tot     alloc    %tot
 ──────────────────────────────────────────────────────────────────
 essential/ad                  1     194s    9.4%   29.5GiB   10.4%
 inference/AdvancedSMC         1   12.2ms    0.0%    239KiB    0.0%
 inference/emcee               1    8.90s    0.4%   2.12GiB    0.7%
 inference/ess                 1   46.4ms    0.0%   2.03MiB    0.0%
 inference/is                  1   2.71ms    0.0%   52.2KiB    0.0%
 inference: forwarddiff        1     642s   31.1%    101GiB   35.6%
   mh                          1   10.6ms    0.0%    222KiB    0.0%
   sghmc                       1   6.52ms    0.0%    123KiB    0.0%
   dynamichmc                  1     134s    6.5%   10.7GiB    3.8%
   Inference                   1     507s   24.6%   90.0GiB   31.8%
   hmc                         1   17.2ms    0.0%   1.21MiB    0.0%
   gibbs_conditional           1   5.73ms    0.0%    104KiB    0.0%
   gibbs                       1   8.20ms    0.0%    148KiB    0.0%
 variational/advi              3   11.2ms    0.0%    240KiB    0.0%
 ModeEstimation                3    21.1s    1.0%   2.38GiB    0.8%
 OptimInterface                3    34.9s    1.7%   6.25GiB    2.2%
 inference: tracker            1     526s   25.5%   65.5GiB   23.1%
   mh                          1   8.95ms    0.0%    222KiB    0.0%
   sghmc                       1   6.01ms    0.0%    123KiB    0.0%
   dynamichmc                  1     118s    5.7%   12.3GiB    4.4%
   Inference                   1     408s   19.8%   53.1GiB   18.8%
   hmc                         1   11.0ms    0.0%    235KiB    0.0%
   gibbs_conditional           1   5.41ms    0.0%    104KiB    0.0%
   gibbs                       1   7.39ms    0.0%    148KiB    0.0%
 inference: reversediff        1     540s   26.2%   60.0GiB   21.2%
   mh                          1   9.60ms    0.0%    222KiB    0.0%
   sghmc                       1   6.43ms    0.0%    123KiB    0.0%
   dynamichmc                  1     118s    5.7%   10.4GiB    3.7%
   Inference                   1     422s   20.5%   49.6GiB   17.5%
   hmc                         1   11.2ms    0.0%    235KiB    0.0%
   gibbs_conditional           1   5.59ms    0.0%    104KiB    0.0%
   gibbs                       1   7.52ms    0.0%    148KiB    0.0%
 optimisers                    1    9.24s    0.4%   5.30GiB    1.9%
 distributions                 1   6.71ms    0.0%    111KiB    0.0%
 RandomMeasures                1    11.6s    0.6%   1.60GiB    0.6%
 utilities                     1    76.4s    3.7%   9.56GiB    3.4%
 ──────────────────────────────────────────────────────────────────

It is also problematic in general to write into the package directory, it might be read-only (IIRC there were also discussions about possibly making them immutable at some point in the future).

I'm not sure how I can write to a temporary directory without either hardcoding the temporary filename or passing it via GitHub Actions env from one step to the next. Both seem not so ideal, so I now removed the functionality altogether. The time and allocations information is now only shown at the end of the julia-actions/julia-runtest@latest step.

EDIT: Wrong nesting fixed in 8430bf7.

@rikhuijzer rikhuijzer requested review from yebai and devmotion March 4, 2022 09:00
@rikhuijzer
Copy link
Contributor Author

From Stan-CI / test (1.6, ubuntu-latest, x64):

 ──────────────────────────────────────────────────────────────────
                                        Time          Allocations  
                                  ───────────────   ───────────────
          Total measured:              2405s             277GiB    

 Section                  ncalls     time    %tot     alloc    %tot
 ──────────────────────────────────────────────────────────────────
 essential/ad                  1     288s   12.0%   34.5GiB   12.4%
 inference/AdvancedSMC         1   11.6ms    0.0%    335KiB    0.0%
 inference/emcee               1    13.6s    0.6%   2.69GiB    1.0%
 inference/ess                 1   51.0ms    0.0%   2.25MiB    0.0%
 inference/is                  1   2.78ms    0.0%   65.0KiB    0.0%
 inference: forwarddiff        1     812s   33.8%    106GiB   38.3%
   OptimInterface              1    39.0s    1.6%   5.72GiB    2.1%
   ModeEstimation              1    25.9s    1.1%   2.48GiB    0.9%
   variational/advi            1   3.96ms    0.0%    117KiB    0.0%
   mh                          1   10.3ms    0.0%    299KiB    0.0%
   sghmc                       1   6.37ms    0.0%    188KiB    0.0%
   dynamichmc                  1   1.08ms    0.0%   13.2KiB    0.0%
   Inference                   1     747s   31.1%   97.9GiB   35.3%
   hmc                         1   18.9ms    0.0%   0.99MiB    0.0%
   gibbs_conditional           1   5.99ms    0.0%    131KiB    0.0%
   gibbs                       1   7.53ms    0.0%    204KiB    0.0%
 inference: tracker            1     575s   23.9%   59.3GiB   21.4%
   OptimInterface              1    8.05s    0.3%   0.96GiB    0.3%
   ModeEstimation              1    755ms    0.0%   51.7MiB    0.0%
   variational/advi            1   3.88ms    0.0%    117KiB    0.0%
   mh                          1   10.0ms    0.0%    299KiB    0.0%
   sghmc                       1   6.20ms    0.0%    188KiB    0.0%
   dynamichmc                  1   1.03ms    0.0%   13.2KiB    0.0%
   Inference                   1     566s   23.6%   58.3GiB   21.0%
   hmc                         1   13.3ms    0.0%    313KiB    0.0%
   gibbs_conditional           1   6.09ms    0.0%    131KiB    0.0%
   gibbs                       1   7.82ms    0.0%    204KiB    0.0%
 inference: reversediff        1     577s   24.0%   56.8GiB   20.5%
   OptimInterface              1    8.26s    0.3%   0.95GiB    0.3%
   ModeEstimation              1    1.30s    0.1%   71.8MiB    0.0%
   variational/advi            1   3.85ms    0.0%    117KiB    0.0%
   mh                          1   10.0ms    0.0%    299KiB    0.0%
   sghmc                       1   6.16ms    0.0%    188KiB    0.0%
   dynamichmc                  1   1.02ms    0.0%   13.2KiB    0.0%
   Inference                   1     567s   23.6%   55.8GiB   20.2%
   hmc                         1   12.8ms    0.0%    313KiB    0.0%
   gibbs_conditional           1   5.94ms    0.0%    131KiB    0.0%
   gibbs                       1   7.60ms    0.0%    204KiB    0.0%
 optimisers                    1    14.8s    0.6%   5.39GiB    1.9%
 distributions                 1   6.85ms    0.0%    156KiB    0.0%
 RandomMeasures                1    15.4s    0.6%   1.68GiB    0.6%
 utilities                     1     107s    4.5%   10.5GiB    3.8%
 ──────────────────────────────────────────────────────────────────

@rikhuijzer
Copy link
Contributor Author

rikhuijzer commented Mar 4, 2022

The wrong ordering of the sub-elements is an upstream bug. I'll try to open a PR there. MWE:

julia> using TimerOutputs

julia> to = TimerOutput();

julia> @timeit to "group" begin
           @timeit to "sub1" sleep(0.1)
           @timeit to "sub2" sleep(0.1)
       end

julia> print_timer(to; compact=true, sortby=:firstexec)
 ───────────────────────────────────────────────────
                         Time          Allocations
                   ───────────────   ───────────────
  Total measured:       46.0s            2.29MiB

 Section   ncalls     time    %tot     alloc    %tot
 ───────────────────────────────────────────────────
 group          1    202ms  100.0%   2.55KiB  100.0%
   sub2         1    101ms   50.0%      320B   12.3%
   sub1         1    101ms   50.0%      320B   12.3%
 ───────────────────────────────────────────────────

EDIT: PR at KristofferC/TimerOutputs.jl#144.

Copy link
Member

@devmotion devmotion left a comment

Choose a reason for hiding this comment

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

I like this much more 🙂 I think the summary can be useful, and have only minor suggestions.

Co-authored-by: David Widmann <devmotion@users.noreply.github.com>
@coveralls
Copy link

coveralls commented Mar 4, 2022

Pull Request Test Coverage Report for Build 1935495446

  • 0 of 0 changed or added relevant lines in 0 files are covered.
  • No unchanged relevant lines lost coverage.
  • Overall coverage remained the same at 81.702%

Totals Coverage Status
Change from base Build 1897322262: 0.0%
Covered Lines: 1219
Relevant Lines: 1492

💛 - Coveralls

@codecov
Copy link

codecov bot commented Mar 4, 2022

Codecov Report

Merging #1787 (5ba2536) into master (02170ed) will not change coverage.
The diff coverage is n/a.

Impacted file tree graph

@@           Coverage Diff           @@
##           master    #1787   +/-   ##
=======================================
  Coverage   81.70%   81.70%           
=======================================
  Files          24       24           
  Lines        1492     1492           
=======================================
  Hits         1219     1219           
  Misses        273      273           

Continue to review full report at Codecov.

Legend - Click here to learn more
Δ = absolute <relative> (impact), ø = not affected, ? = missing data
Powered by Codecov. Last update 02170ed...5ba2536. Read the comment docs.

@KristofferC
Copy link

You could also take a look at https://github.com/Ferrite-FEM/Tensors.jl/blob/f2d296bc4f75f803f5dca931b6dfd642637733d1/test/runtests.jl#L8-L16. Then you can just use @testsection as a replacement of @testset and it will get added to the timer.

@rikhuijzer
Copy link
Contributor Author

You could also take a look at https://github.com/Ferrite-FEM/Tensors.jl/blob/f2d296bc4f75f803f5dca931b6dfd642637733d1/test/runtests.jl#L8-L16. Then you can just use @testsection as a replacement of @testset and it will get added to the timer.

Could we maybe use something less intrusive, without all the special commands? I think this leads to a quite unidiomatic and surprising test structure. Maybe we could use https://github.com/KristofferC/TimerOutputs.jl or something similar?

@devmotion what has your preference? The @testsection is nice but could also be considered "surprising" for readers.

@devmotion
Copy link
Member

Since we only use it in test/runtests.jl I guess it's sufficiently clear and unsurprising for a reader if we define a similar convenience macro for @timeit to ... include(...) at the top of that file. Maybe even more obvious if we would call it eg @timeit_include.

@rikhuijzer rikhuijzer changed the title Show timing information in a clear way Show timing and allocations for tests Mar 4, 2022
Copy link
Member

@devmotion devmotion left a comment

Choose a reason for hiding this comment

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

Looks good, I left some final comments.

Co-authored-by: David Widmann <devmotion@users.noreply.github.com>
@rikhuijzer rikhuijzer merged commit 22772bd into master Mar 5, 2022
@delete-merged-branch delete-merged-branch bot deleted the rh/measure-tests branch March 5, 2022 07:17
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

Successfully merging this pull request may close these issues.

5 participants