From 78a5e2bd1804a8d75deb5fa3df62c48642b1da01 Mon Sep 17 00:00:00 2001 From: Rik Huijzer Date: Thu, 3 Mar 2022 22:14:33 +0100 Subject: [PATCH 1/8] Show timing information in a clear way --- .github/workflows/TuringCI.yml | 2 ++ test/Project.toml | 8 ++++-- test/runtests.jl | 50 +++++++++++++++++++--------------- test/test_utils/timing.jl | 37 +++++++++++++++++++++++++ 4 files changed, 73 insertions(+), 24 deletions(-) create mode 100644 test/test_utils/timing.jl diff --git a/.github/workflows/TuringCI.yml b/.github/workflows/TuringCI.yml index b54c35084a..5044ae219f 100644 --- a/.github/workflows/TuringCI.yml +++ b/.github/workflows/TuringCI.yml @@ -57,6 +57,8 @@ jobs: coverage: ${{ matrix.version == '1.6' && matrix.os == 'ubuntu-latest' && matrix.num_threads == 1 }} env: JULIA_NUM_THREADS: ${{ matrix.num_threads }} + - name: Show running time output + run: cat benchmarks/outputs/times.txt - uses: julia-actions/julia-processcoverage@v1 if: matrix.version == '1.6' && matrix.os == 'ubuntu-latest' && matrix.num_threads == 1 - uses: codecov/codecov-action@v1 diff --git a/test/Project.toml b/test/Project.toml index 1c1ffc16d1..4454591b81 100644 --- a/test/Project.toml +++ b/test/Project.toml @@ -5,6 +5,7 @@ AdvancedPS = "576499cb-2369-40b2-a588-c64705576edc" AdvancedVI = "b5ca4192-6429-45e5-a2d9-87aec30a685c" Clustering = "aaaa29a8-35af-508c-8bc3-b662a17a0fe5" CmdStan = "593b3428-ca2f-500c-ae53-031589ec8ddd" +DataFrames = "a93c6f00-e57d-5684-b7b6-d8193f3e46c0" Distributions = "31c24e10-a181-5473-b8eb-7969acd0382f" DistributionsAD = "ced4e74d-a319-5a8a-b0ac-84af2272839c" DynamicHMC = "bbc10e6e-7c05-544b-b16e-64fede858acb" @@ -17,17 +18,18 @@ MCMCChains = "c7f686f2-ff18-58e9-bc7b-31028e88f75d" Memoization = "6fafb56a-5788-4b4e-91ca-c0cea6611c73" NamedArrays = "86f7a689-2022-50b4-a561-43c23ac3c673" Optim = "429524aa-4258-5aef-a3af-852621145aeb" +OrderedCollections = "bac558e1-5e72-5ebc-8fee-abe8a469f55d" PDMats = "90014a1f-27ba-587c-ab20-58faa44d9150" Pkg = "44cfe95a-1eb2-52ea-b672-e2afdf69b78f" Random = "9a3f8284-a2c9-5f02-9a11-845980a1fd5c" ReverseDiff = "37e2e3b7-166d-5795-8a7a-e32c996b4267" SpecialFunctions = "276daf66-3868-5448-9aa4-cd146d93841b" +StableRNGs = "860ef19b-820b-49d6-a774-d7a799459cd3" StatsBase = "2913bbd2-ae8a-5f71-8c99-4fb6c76f3a91" StatsFuns = "4c63d2b9-4356-54db-8cca-17b64c39e42c" Test = "8dfed614-e22c-5e08-85e1-65c5234f0b40" Tracker = "9f7883ad-71c0-57eb-9f7f-b5c9e6d3789c" Zygote = "e88e6eb3-aa80-5325-afca-941959d7151f" -StableRNGs = "860ef19b-820b-49d6-a774-d7a799459cd3" [compat] AbstractMCMC = "3.2.1" @@ -36,6 +38,7 @@ AdvancedPS = "0.3" AdvancedVI = "0.1" Clustering = "0.14" CmdStan = "6.0.8" +DataFrames = "1" Distributions = "0.25" DistributionsAD = "0.6.3" DynamicHMC = "2.1.6, 3.0" @@ -47,12 +50,13 @@ MCMCChains = "5" Memoization = "0.1.4" NamedArrays = "0.9.4" Optim = "0.22, 1.0" +OrderedCollections = "1" PDMats = "0.10, 0.11" ReverseDiff = "1.4.2" SpecialFunctions = "0.10.3, 1, 2" +StableRNGs = "1" StatsBase = "0.33" StatsFuns = "0.9.5" Tracker = "0.2.11" Zygote = "0.5.4, 0.6" -StableRNGs = "1" julia = "1.3" diff --git a/test/runtests.jl b/test/runtests.jl index bdc64df8f3..c9a5e209b7 100644 --- a/test/runtests.jl +++ b/test/runtests.jl @@ -11,6 +11,7 @@ using MCMCChains using Memoization using NamedArrays using Optim +using OrderedCollections using PDMats using ReverseDiff using SpecialFunctions @@ -30,10 +31,12 @@ using StableRNGs using AdvancedPS: ResampleWithESSThreshold, resample_systematic, resample_multinomial using AdvancedVI: TruncatedADAGrad, DecayedADAGrad, apply! +using DataFrames: DataFrame using Distributions: Binomial, logpdf using DynamicPPL: getval, getlogp using ForwardDiff: Dual using MCMCChains: Chains +using OrderedCollections: OrderedDict using StatsFuns: binomlogpdf, logistic, logsumexp using Turing: BinomialLogit, ForwardDiffAD, Sampler, SampleFromPrior, NUTS, TrackerAD, Variational, ZygoteAD, getspace, gradient_logp @@ -44,16 +47,19 @@ setprogress!(false) include(pkgdir(Turing)*"/test/test_utils/AllUtils.jl") +# Collect timing and allocations information to show in a clear way. +include(pkgdir(Turing)*"/test/test_utils/timing.jl") + @testset "Turing" begin @testset "essential" begin - include("essential/ad.jl") + time_include("essential/ad.jl") end @testset "samplers (without AD)" begin - include("inference/AdvancedSMC.jl") - include("inference/emcee.jl") - include("inference/ess.jl") - include("inference/is.jl") + time_include("inference/AdvancedSMC.jl") + time_include("inference/emcee.jl") + time_include("inference/ess.jl") + time_include("inference/is.jl") end Turing.setrdcache(false) @@ -63,42 +69,42 @@ include(pkgdir(Turing)*"/test/test_utils/AllUtils.jl") start = time() @testset "inference: $adbackend" begin @testset "samplers" begin - include("inference/gibbs.jl") - include("inference/gibbs_conditional.jl") - include("inference/hmc.jl") - include("inference/Inference.jl") - include("contrib/inference/dynamichmc.jl") - include("contrib/inference/sghmc.jl") - include("inference/mh.jl") + time_include("inference/gibbs.jl", adbackend) + time_include("inference/gibbs_conditional.jl", adbackend) + time_include("inference/hmc.jl", adbackend) + time_include("inference/Inference.jl", adbackend) + time_include("contrib/inference/dynamichmc.jl", adbackend) + time_include("contrib/inference/sghmc.jl", adbackend) + time_include("inference/mh.jl", adbackend) end end @testset "variational algorithms : $adbackend" begin - include("variational/advi.jl") + time_include("variational/advi.jl", adbackend) end @testset "modes" begin - include("modes/ModeEstimation.jl") - include("modes/OptimInterface.jl") + time_include("modes/ModeEstimation.jl", adbackend) + time_include("modes/OptimInterface.jl", adbackend) end - # Useful for - # a) discovering performance regressions, - # b) figuring out why CI is timing out. + # Useful for figuring out why CI is timing out. @info "Tests for $(adbackend) took $(time() - start) seconds" end @testset "variational optimisers" begin - include("variational/optimisers.jl") + time_include("variational/optimisers.jl") end Turing.setadbackend(:forwarddiff) @testset "stdlib" begin - include("stdlib/distributions.jl") - include("stdlib/RandomMeasures.jl") + time_include("stdlib/distributions.jl", :forwarddiff) + time_include("stdlib/RandomMeasures.jl", :forwarddiff) end @testset "utilities" begin # include("utilities/stan-interface.jl") - include("inference/utilities.jl") + time_include("inference/utilities.jl") end end + +print(write_running_times(TIMES)) diff --git a/test/test_utils/timing.jl b/test/test_utils/timing.jl new file mode 100644 index 0000000000..d8bb956afd --- /dev/null +++ b/test/test_utils/timing.jl @@ -0,0 +1,37 @@ +const TIMES = OrderedDict() + +# To get rid of Julia's compile time. +TIMES["warmup"] = @timed 1 + 1 + +function time_include(path, group=nothing) + key = isnothing(group) ? path : "$group - $path" + TIMES[key] = @timed include(path) +end + +"Return a string of pretty printed running times based on TIMES." +function running_times(times)::String + tcopy = deepcopy(times) + pop!(tcopy, "warmup") + names = [first(x) for x in tcopy] + times = [round(last(x).time; digits=1) for x in tcopy] + allocations = [round(last(x).bytes / 10^9; digits=1) for x in tcopy] + df = DataFrame( + "Test" => names, + "Allocations (GB)" => allocations, + "Time (seconds)" => times + ) + pretty_printed = string(df) + return """ + $pretty_printed + + Note that the reported times differ between GitHub Runners due to different CPUs; allocations are more stable. + """ +end + +function write_running_times(times) + text = running_times(times) + path = joinpath(pkgdir(Turing), "benchmarks", "output", "times.txt") + mkdir(dirname(path)) + write(path, text) + return text +end From f4ab40b7fe8df58065f6b0b7b98d363c3e8f73f3 Mon Sep 17 00:00:00 2001 From: Rik Huijzer Date: Fri, 4 Mar 2022 08:58:05 +0100 Subject: [PATCH 2/8] Switch to TimerOutputs --- .github/workflows/TuringCI.yml | 2 -- Project.toml | 1 + test/Project.toml | 5 +--- test/runtests.jl | 52 +++++++++++++++++----------------- test/test_utils/timing.jl | 37 ------------------------ 5 files changed, 28 insertions(+), 69 deletions(-) delete mode 100644 test/test_utils/timing.jl diff --git a/.github/workflows/TuringCI.yml b/.github/workflows/TuringCI.yml index 5044ae219f..b54c35084a 100644 --- a/.github/workflows/TuringCI.yml +++ b/.github/workflows/TuringCI.yml @@ -57,8 +57,6 @@ jobs: coverage: ${{ matrix.version == '1.6' && matrix.os == 'ubuntu-latest' && matrix.num_threads == 1 }} env: JULIA_NUM_THREADS: ${{ matrix.num_threads }} - - name: Show running time output - run: cat benchmarks/outputs/times.txt - uses: julia-actions/julia-processcoverage@v1 if: matrix.version == '1.6' && matrix.os == 'ubuntu-latest' && matrix.num_threads == 1 - uses: codecov/codecov-action@v1 diff --git a/Project.toml b/Project.toml index 7a097b13bf..33bd4dbde8 100644 --- a/Project.toml +++ b/Project.toml @@ -57,6 +57,7 @@ SciMLBase = "1.8.1" SpecialFunctions = "0.7.2, 0.8, 0.9, 0.10, 1, 2" StatsBase = "0.32, 0.33" StatsFuns = "0.8, 0.9" +TimerOutputs = "0.5" Tracker = "0.2.3" ZygoteRules = "0.2" julia = "1.6" diff --git a/test/Project.toml b/test/Project.toml index 4454591b81..12557ea60b 100644 --- a/test/Project.toml +++ b/test/Project.toml @@ -5,7 +5,6 @@ AdvancedPS = "576499cb-2369-40b2-a588-c64705576edc" AdvancedVI = "b5ca4192-6429-45e5-a2d9-87aec30a685c" Clustering = "aaaa29a8-35af-508c-8bc3-b662a17a0fe5" CmdStan = "593b3428-ca2f-500c-ae53-031589ec8ddd" -DataFrames = "a93c6f00-e57d-5684-b7b6-d8193f3e46c0" Distributions = "31c24e10-a181-5473-b8eb-7969acd0382f" DistributionsAD = "ced4e74d-a319-5a8a-b0ac-84af2272839c" DynamicHMC = "bbc10e6e-7c05-544b-b16e-64fede858acb" @@ -18,7 +17,6 @@ MCMCChains = "c7f686f2-ff18-58e9-bc7b-31028e88f75d" Memoization = "6fafb56a-5788-4b4e-91ca-c0cea6611c73" NamedArrays = "86f7a689-2022-50b4-a561-43c23ac3c673" Optim = "429524aa-4258-5aef-a3af-852621145aeb" -OrderedCollections = "bac558e1-5e72-5ebc-8fee-abe8a469f55d" PDMats = "90014a1f-27ba-587c-ab20-58faa44d9150" Pkg = "44cfe95a-1eb2-52ea-b672-e2afdf69b78f" Random = "9a3f8284-a2c9-5f02-9a11-845980a1fd5c" @@ -28,6 +26,7 @@ StableRNGs = "860ef19b-820b-49d6-a774-d7a799459cd3" StatsBase = "2913bbd2-ae8a-5f71-8c99-4fb6c76f3a91" StatsFuns = "4c63d2b9-4356-54db-8cca-17b64c39e42c" Test = "8dfed614-e22c-5e08-85e1-65c5234f0b40" +TimerOutputs = "a759f4b9-e2f1-59dc-863e-4aeb61b1ea8f" Tracker = "9f7883ad-71c0-57eb-9f7f-b5c9e6d3789c" Zygote = "e88e6eb3-aa80-5325-afca-941959d7151f" @@ -38,7 +37,6 @@ AdvancedPS = "0.3" AdvancedVI = "0.1" Clustering = "0.14" CmdStan = "6.0.8" -DataFrames = "1" Distributions = "0.25" DistributionsAD = "0.6.3" DynamicHMC = "2.1.6, 3.0" @@ -50,7 +48,6 @@ MCMCChains = "5" Memoization = "0.1.4" NamedArrays = "0.9.4" Optim = "0.22, 1.0" -OrderedCollections = "1" PDMats = "0.10, 0.11" ReverseDiff = "1.4.2" SpecialFunctions = "0.10.3, 1, 2" diff --git a/test/runtests.jl b/test/runtests.jl index c9a5e209b7..4faceb6771 100644 --- a/test/runtests.jl +++ b/test/runtests.jl @@ -11,7 +11,6 @@ using MCMCChains using Memoization using NamedArrays using Optim -using OrderedCollections using PDMats using ReverseDiff using SpecialFunctions @@ -31,13 +30,12 @@ using StableRNGs using AdvancedPS: ResampleWithESSThreshold, resample_systematic, resample_multinomial using AdvancedVI: TruncatedADAGrad, DecayedADAGrad, apply! -using DataFrames: DataFrame using Distributions: Binomial, logpdf using DynamicPPL: getval, getlogp using ForwardDiff: Dual using MCMCChains: Chains -using OrderedCollections: OrderedDict using StatsFuns: binomlogpdf, logistic, logsumexp +using TimerOutputs: TimerOutput, @timeit, print_timer using Turing: BinomialLogit, ForwardDiffAD, Sampler, SampleFromPrior, NUTS, TrackerAD, Variational, ZygoteAD, getspace, gradient_logp using Turing.Essential: TuringDenseMvNormal, TuringDiagMvNormal @@ -48,18 +46,18 @@ setprogress!(false) include(pkgdir(Turing)*"/test/test_utils/AllUtils.jl") # Collect timing and allocations information to show in a clear way. -include(pkgdir(Turing)*"/test/test_utils/timing.jl") +const to = TimerOutput() @testset "Turing" begin @testset "essential" begin - time_include("essential/ad.jl") + @timeit to "essential/ad" include("essential/ad.jl") end @testset "samplers (without AD)" begin - time_include("inference/AdvancedSMC.jl") - time_include("inference/emcee.jl") - time_include("inference/ess.jl") - time_include("inference/is.jl") + @timeit to "inference/AdvancedSMC" include("inference/AdvancedSMC.jl") + @timeit to "inference/emcee" include("inference/emcee.jl") + @timeit to "inference/ess" include("inference/ess.jl") + @timeit to "inference/is" include("inference/is.jl") end Turing.setrdcache(false) @@ -67,44 +65,46 @@ include(pkgdir(Turing)*"/test/test_utils/timing.jl") Turing.setadbackend(adbackend) @info "Testing $(adbackend)" start = time() - @testset "inference: $adbackend" begin - @testset "samplers" begin - time_include("inference/gibbs.jl", adbackend) - time_include("inference/gibbs_conditional.jl", adbackend) - time_include("inference/hmc.jl", adbackend) - time_include("inference/Inference.jl", adbackend) - time_include("contrib/inference/dynamichmc.jl", adbackend) - time_include("contrib/inference/sghmc.jl", adbackend) - time_include("inference/mh.jl", adbackend) + @timeit to "inference: $adbackend" begin + @testset "inference: $adbackend" begin + @testset "samplers" begin + @timeit to "gibbs" include("inference/gibbs.jl") + @timeit to "gibbs_conditional" include("inference/gibbs_conditional.jl") + @timeit to "hmc" include("inference/hmc.jl") + @timeit to "Inference" include("inference/Inference.jl") + @timeit to "dynamichmc" include("contrib/inference/dynamichmc.jl") + @timeit to "sghmc" include("contrib/inference/sghmc.jl") + @timeit to "mh" include("inference/mh.jl") + end end end @testset "variational algorithms : $adbackend" begin - time_include("variational/advi.jl", adbackend) + @timeit to "variational/advi" include("variational/advi.jl") end @testset "modes" begin - time_include("modes/ModeEstimation.jl", adbackend) - time_include("modes/OptimInterface.jl", adbackend) + @timeit to "ModeEstimation" include("modes/ModeEstimation.jl") + @timeit to "OptimInterface" include("modes/OptimInterface.jl") end # Useful for figuring out why CI is timing out. @info "Tests for $(adbackend) took $(time() - start) seconds" end @testset "variational optimisers" begin - time_include("variational/optimisers.jl") + @timeit to "optimisers" include("variational/optimisers.jl") end Turing.setadbackend(:forwarddiff) @testset "stdlib" begin - time_include("stdlib/distributions.jl", :forwarddiff) - time_include("stdlib/RandomMeasures.jl", :forwarddiff) + @timeit to "distributions" include("stdlib/distributions.jl") + @timeit to "RandomMeasures" include("stdlib/RandomMeasures.jl") end @testset "utilities" begin # include("utilities/stan-interface.jl") - time_include("inference/utilities.jl") + @timeit to "utilities" include("inference/utilities.jl") end end -print(write_running_times(TIMES)) +print_timer(to; sortby=:firstexec) diff --git a/test/test_utils/timing.jl b/test/test_utils/timing.jl deleted file mode 100644 index d8bb956afd..0000000000 --- a/test/test_utils/timing.jl +++ /dev/null @@ -1,37 +0,0 @@ -const TIMES = OrderedDict() - -# To get rid of Julia's compile time. -TIMES["warmup"] = @timed 1 + 1 - -function time_include(path, group=nothing) - key = isnothing(group) ? path : "$group - $path" - TIMES[key] = @timed include(path) -end - -"Return a string of pretty printed running times based on TIMES." -function running_times(times)::String - tcopy = deepcopy(times) - pop!(tcopy, "warmup") - names = [first(x) for x in tcopy] - times = [round(last(x).time; digits=1) for x in tcopy] - allocations = [round(last(x).bytes / 10^9; digits=1) for x in tcopy] - df = DataFrame( - "Test" => names, - "Allocations (GB)" => allocations, - "Time (seconds)" => times - ) - pretty_printed = string(df) - return """ - $pretty_printed - - Note that the reported times differ between GitHub Runners due to different CPUs; allocations are more stable. - """ -end - -function write_running_times(times) - text = running_times(times) - path = joinpath(pkgdir(Turing), "benchmarks", "output", "times.txt") - mkdir(dirname(path)) - write(path, text) - return text -end From 60c146e88257a9977f2fcbd03548d29434ec19b7 Mon Sep 17 00:00:00 2001 From: Rik Huijzer Date: Fri, 4 Mar 2022 08:59:18 +0100 Subject: [PATCH 3/8] Add compat to right Project --- Project.toml | 1 - test/Project.toml | 1 + 2 files changed, 1 insertion(+), 1 deletion(-) diff --git a/Project.toml b/Project.toml index 33bd4dbde8..7a097b13bf 100644 --- a/Project.toml +++ b/Project.toml @@ -57,7 +57,6 @@ SciMLBase = "1.8.1" SpecialFunctions = "0.7.2, 0.8, 0.9, 0.10, 1, 2" StatsBase = "0.32, 0.33" StatsFuns = "0.8, 0.9" -TimerOutputs = "0.5" Tracker = "0.2.3" ZygoteRules = "0.2" julia = "1.6" diff --git a/test/Project.toml b/test/Project.toml index 12557ea60b..04ab464668 100644 --- a/test/Project.toml +++ b/test/Project.toml @@ -54,6 +54,7 @@ SpecialFunctions = "0.10.3, 1, 2" StableRNGs = "1" StatsBase = "0.33" StatsFuns = "0.9.5" +TimerOutputs = "0.5" Tracker = "0.2.11" Zygote = "0.5.4, 0.6" julia = "1.3" From 950ea621a75d1ca7d855323d967cd4d2fe8aded3 Mon Sep 17 00:00:00 2001 From: Rik Huijzer Date: Fri, 4 Mar 2022 09:03:52 +0100 Subject: [PATCH 4/8] Set compact=true --- test/runtests.jl | 3 ++- 1 file changed, 2 insertions(+), 1 deletion(-) diff --git a/test/runtests.jl b/test/runtests.jl index 4faceb6771..fef7a23cf4 100644 --- a/test/runtests.jl +++ b/test/runtests.jl @@ -107,4 +107,5 @@ const to = TimerOutput() end end -print_timer(to; sortby=:firstexec) +# Hiding `avg` column via `compact=true` because we do only one run per entry. +print_timer(to; compact=true, sortby=:firstexec) From 8430bf7b2090d88291e7a80dc5d690a528eb4df3 Mon Sep 17 00:00:00 2001 From: Rik Huijzer Date: Fri, 4 Mar 2022 09:52:58 +0100 Subject: [PATCH 5/8] Fix nesting of `adbackend` --- test/runtests.jl | 27 ++++++++++++++------------- 1 file changed, 14 insertions(+), 13 deletions(-) diff --git a/test/runtests.jl b/test/runtests.jl index fef7a23cf4..3f75ccd2b1 100644 --- a/test/runtests.jl +++ b/test/runtests.jl @@ -62,10 +62,10 @@ const to = TimerOutput() Turing.setrdcache(false) for adbackend in (:forwarddiff, :tracker, :reversediff) - Turing.setadbackend(adbackend) - @info "Testing $(adbackend)" - start = time() @timeit to "inference: $adbackend" begin + Turing.setadbackend(adbackend) + @info "Testing $(adbackend)" + start = time() @testset "inference: $adbackend" begin @testset "samplers" begin @timeit to "gibbs" include("inference/gibbs.jl") @@ -77,20 +77,21 @@ const to = TimerOutput() @timeit to "mh" include("inference/mh.jl") end end - end - @testset "variational algorithms : $adbackend" begin - @timeit to "variational/advi" include("variational/advi.jl") - end + @testset "variational algorithms : $adbackend" begin + @timeit to "variational/advi" include("variational/advi.jl") + end - @testset "modes" begin - @timeit to "ModeEstimation" include("modes/ModeEstimation.jl") - @timeit to "OptimInterface" include("modes/OptimInterface.jl") - end + @testset "modes : $adbackend" begin + @timeit to "ModeEstimation" include("modes/ModeEstimation.jl") + @timeit to "OptimInterface" include("modes/OptimInterface.jl") + end - # Useful for figuring out why CI is timing out. - @info "Tests for $(adbackend) took $(time() - start) seconds" + # Useful for figuring out why CI is timing out. + @info "Tests for $(adbackend) took $(time() - start) seconds" + end end + @testset "variational optimisers" begin @timeit to "optimisers" include("variational/optimisers.jl") end From f8fd78936efee2f02becc50b213c8ffe07e53e6e Mon Sep 17 00:00:00 2001 From: Rik Huijzer Date: Fri, 4 Mar 2022 11:41:52 +0100 Subject: [PATCH 6/8] Apply suggestions from code review Co-authored-by: David Widmann --- test/runtests.jl | 6 +++--- 1 file changed, 3 insertions(+), 3 deletions(-) diff --git a/test/runtests.jl b/test/runtests.jl index 3f75ccd2b1..73133ac1fd 100644 --- a/test/runtests.jl +++ b/test/runtests.jl @@ -35,7 +35,7 @@ using DynamicPPL: getval, getlogp using ForwardDiff: Dual using MCMCChains: Chains using StatsFuns: binomlogpdf, logistic, logsumexp -using TimerOutputs: TimerOutput, @timeit, print_timer +using TimerOutputs: TimerOutputs, @timeit using Turing: BinomialLogit, ForwardDiffAD, Sampler, SampleFromPrior, NUTS, TrackerAD, Variational, ZygoteAD, getspace, gradient_logp using Turing.Essential: TuringDenseMvNormal, TuringDiagMvNormal @@ -46,7 +46,7 @@ setprogress!(false) include(pkgdir(Turing)*"/test/test_utils/AllUtils.jl") # Collect timing and allocations information to show in a clear way. -const to = TimerOutput() +const to = TimerOutputs.TimerOutput() @testset "Turing" begin @testset "essential" begin @@ -109,4 +109,4 @@ const to = TimerOutput() end # Hiding `avg` column via `compact=true` because we do only one run per entry. -print_timer(to; compact=true, sortby=:firstexec) +show(to; compact=true, sortby=:firstexec) From da2253bd0fc4bd39eaaa872211ae5222bcc410a2 Mon Sep 17 00:00:00 2001 From: Rik Huijzer Date: Fri, 4 Mar 2022 15:58:59 +0100 Subject: [PATCH 7/8] Add `@timeit_include` macro --- test/runtests.jl | 48 +++++++++++++++++++++++++----------------------- 1 file changed, 25 insertions(+), 23 deletions(-) diff --git a/test/runtests.jl b/test/runtests.jl index 73133ac1fd..a69dcd7cd2 100644 --- a/test/runtests.jl +++ b/test/runtests.jl @@ -46,45 +46,48 @@ setprogress!(false) include(pkgdir(Turing)*"/test/test_utils/AllUtils.jl") # Collect timing and allocations information to show in a clear way. -const to = TimerOutputs.TimerOutput() +const TIMEROUTPUT = TimerOutputs.TimerOutput() +macro timeit_include(path::AbstractString) + return :(@timeit TIMEROUTPUT $path include($path)) +end @testset "Turing" begin @testset "essential" begin - @timeit to "essential/ad" include("essential/ad.jl") + @timeit_include("essential/ad.jl") end @testset "samplers (without AD)" begin - @timeit to "inference/AdvancedSMC" include("inference/AdvancedSMC.jl") - @timeit to "inference/emcee" include("inference/emcee.jl") - @timeit to "inference/ess" include("inference/ess.jl") - @timeit to "inference/is" include("inference/is.jl") + @timeit_include("inference/AdvancedSMC.jl") + @timeit_include("inference/emcee.jl") + @timeit_include("inference/ess.jl") + @timeit_include("inference/is.jl") end Turing.setrdcache(false) for adbackend in (:forwarddiff, :tracker, :reversediff) - @timeit to "inference: $adbackend" begin + @timeit TIMEROUTPUT "inference: $adbackend" begin Turing.setadbackend(adbackend) @info "Testing $(adbackend)" start = time() @testset "inference: $adbackend" begin @testset "samplers" begin - @timeit to "gibbs" include("inference/gibbs.jl") - @timeit to "gibbs_conditional" include("inference/gibbs_conditional.jl") - @timeit to "hmc" include("inference/hmc.jl") - @timeit to "Inference" include("inference/Inference.jl") - @timeit to "dynamichmc" include("contrib/inference/dynamichmc.jl") - @timeit to "sghmc" include("contrib/inference/sghmc.jl") - @timeit to "mh" include("inference/mh.jl") + @timeit_include("inference/gibbs.jl") + @timeit_include("inference/gibbs_conditional.jl") + @timeit_include("inference/hmc.jl") + @timeit_include("inference/Inference.jl") + @timeit_include("contrib/inference/dynamichmc.jl") + @timeit_include("contrib/inference/sghmc.jl") + @timeit_include("inference/mh.jl") end end @testset "variational algorithms : $adbackend" begin - @timeit to "variational/advi" include("variational/advi.jl") + @timeit_include("variational/advi.jl") end @testset "modes : $adbackend" begin - @timeit to "ModeEstimation" include("modes/ModeEstimation.jl") - @timeit to "OptimInterface" include("modes/OptimInterface.jl") + @timeit_include("modes/ModeEstimation.jl") + @timeit_include("modes/OptimInterface.jl") end # Useful for figuring out why CI is timing out. @@ -93,20 +96,19 @@ const to = TimerOutputs.TimerOutput() end @testset "variational optimisers" begin - @timeit to "optimisers" include("variational/optimisers.jl") + @timeit_include("variational/optimisers.jl") end Turing.setadbackend(:forwarddiff) @testset "stdlib" begin - @timeit to "distributions" include("stdlib/distributions.jl") - @timeit to "RandomMeasures" include("stdlib/RandomMeasures.jl") + @timeit_include("stdlib/distributions.jl") + @timeit_include("stdlib/RandomMeasures.jl") end @testset "utilities" begin # include("utilities/stan-interface.jl") - @timeit to "utilities" include("inference/utilities.jl") + @timeit_include("inference/utilities.jl") end end -# Hiding `avg` column via `compact=true` because we do only one run per entry. -show(to; compact=true, sortby=:firstexec) +show(TIMEROUTPUT; compact=true, sortby=:firstexec) From 5ba2536efc75c5dd47fd7d7f854fdfaa5c0316e6 Mon Sep 17 00:00:00 2001 From: Rik Huijzer Date: Fri, 4 Mar 2022 20:21:47 +0100 Subject: [PATCH 8/8] Apply suggestions from code review Co-authored-by: David Widmann --- test/runtests.jl | 7 +------ 1 file changed, 1 insertion(+), 6 deletions(-) diff --git a/test/runtests.jl b/test/runtests.jl index a69dcd7cd2..c5d69031f2 100644 --- a/test/runtests.jl +++ b/test/runtests.jl @@ -47,9 +47,7 @@ include(pkgdir(Turing)*"/test/test_utils/AllUtils.jl") # Collect timing and allocations information to show in a clear way. const TIMEROUTPUT = TimerOutputs.TimerOutput() -macro timeit_include(path::AbstractString) - return :(@timeit TIMEROUTPUT $path include($path)) -end +macro timeit_include(path::AbstractString) :(@timeit TIMEROUTPUT $path include($path)) end @testset "Turing" begin @testset "essential" begin @@ -68,7 +66,6 @@ end @timeit TIMEROUTPUT "inference: $adbackend" begin Turing.setadbackend(adbackend) @info "Testing $(adbackend)" - start = time() @testset "inference: $adbackend" begin @testset "samplers" begin @timeit_include("inference/gibbs.jl") @@ -90,8 +87,6 @@ end @timeit_include("modes/OptimInterface.jl") end - # Useful for figuring out why CI is timing out. - @info "Tests for $(adbackend) took $(time() - start) seconds" end end