diff --git a/Project.toml b/Project.toml index fb13a3c..66d0c4c 100644 --- a/Project.toml +++ b/Project.toml @@ -3,6 +3,9 @@ uuid = "9a0f1c46-06d5-4909-a5a3-ce25d3fa3284" authors = ["Michael Schlottke-Lakemper "] version = "0.1.3-pre" +[deps] +TimerOutputs = "a759f4b9-e2f1-59dc-863e-4aeb61b1ea8f" + [weakdeps] MPI = "da04e1cc-30fd-572f-bb4f-1f8673147195" @@ -11,6 +14,7 @@ TrixiBaseMPIExt = "MPI" [compat] MPI = "0.20" +TimerOutputs = "0.5" julia = "1.8" [extras] diff --git a/src/TrixiBase.jl b/src/TrixiBase.jl index dd7ce03..c4829fa 100644 --- a/src/TrixiBase.jl +++ b/src/TrixiBase.jl @@ -1,8 +1,12 @@ module TrixiBase +using TimerOutputs: TimerOutput, TimerOutputs + include("trixi_include.jl") +include("trixi_timeit.jl") export trixi_include +export @trixi_timeit, timer, timeit_debug_enabled, disable_debug_timings function _precompile_manual_() @assert Base.precompile(Tuple{typeof(trixi_include), String}) diff --git a/src/trixi_timeit.jl b/src/trixi_timeit.jl new file mode 100644 index 0000000..15883db --- /dev/null +++ b/src/trixi_timeit.jl @@ -0,0 +1,43 @@ +# Enable debug timings `@trixi_timeit timer() "name" stuff...`. +# This allows us to disable timings completely by executing +# `TimerOutputs.disable_debug_timings(TrixiBase)` +# and to enable them again by executing +# `TimerOutputs.enable_debug_timings(TrixiBase)` +timeit_debug_enabled() = true +disable_debug_timings() = TimerOutputs.disable_debug_timings(@__MODULE__) +enable_debug_timings() = TimerOutputs.enable_debug_timings(@__MODULE__) + +# Store main timer for global timing of functions +const main_timer = TimerOutput() + +# Always call timer() to hide implementation details +timer() = main_timer + +# @trixi_timeit timer() "some label" expression +# +# Basically the same as a special case of `@timeit_debug` from +# [TimerOutputs.jl](https://github.com/KristofferC/TimerOutputs.jl), +# but without `try ... finally ... end` block. Thus, it's not exception-safe, +# but it also avoids some related performance problems. Since we do not use +# exception handling in Trixi, that's not really an issue. +# +# Copied from [Trixi.jl](https://github.com/trixi-framework/Trixi.jl). +macro trixi_timeit(timer_output, label, expr) + timeit_block = quote + if timeit_debug_enabled() + local to = $(esc(timer_output)) + local enabled = to.enabled + if enabled + local accumulated_data = $(TimerOutputs.push!)(to, $(esc(label))) + end + local b0 = $(TimerOutputs.gc_bytes)() + local t0 = $(TimerOutputs.time_ns)() + end + local val = $(esc(expr)) + if timeit_debug_enabled() && enabled + $(TimerOutputs.do_accumulate!)(accumulated_data, t0, b0) + $(TimerOutputs.pop!)(to) + end + val + end +end diff --git a/test/runtests.jl b/test/runtests.jl index 62d4f2b..b7ae7f7 100644 --- a/test/runtests.jl +++ b/test/runtests.jl @@ -3,4 +3,5 @@ include("test_util.jl") @testset verbose=true "TrixiBase.jl Tests" begin include("test_aqua.jl") include("trixi_include.jl") -end + include("test_timers.jl") +end; diff --git a/test/test_timers.jl b/test/test_timers.jl new file mode 100644 index 0000000..9438c72 --- /dev/null +++ b/test/test_timers.jl @@ -0,0 +1,59 @@ +@testset verbose=true "Timers" begin + @testset verbose=true "`timer()`" begin + @test timer() isa TrixiBase.TimerOutput + + # Test empty timer output + TrixiBase.TimerOutputs.reset_timer!(timer()) + + timer_output = """ + ──────────────────────────────────────────────────────────────────── + Time Allocations + ─────────────────────── ──────────────────────── + Tot / % measured: 91.5s / 0.0% 5.43MiB / 0.0% + + Section ncalls time %tot avg alloc %tot avg + ──────────────────────────────────────────────────────────────────── + ──────────────────────────────────────────────────────────────────── + """ + # Remove "Tot / % measured" line and trailing white spaces + expected = replace(timer_output, r"Tot / % measured: .*" => "", + r"\s+\n" => "\n") + actual = replace(repr(timer()) * "\n", r"Tot / % measured: .*" => "", + r"\s+\n" => "\n") + + # Compare against empty timer output + @test actual == expected + end + + @testset verbose=true "`@trixi_timeit`" begin + # Start with empty timer output + TrixiBase.TimerOutputs.reset_timer!(timer()) + + # Add timer entry with 2 calls + @trixi_timeit timer() "test timer" sin(0.0) + @trixi_timeit timer() "test timer" sin(0.0) + + timer_output = """ + ─────────────────────────────────────────────────────────────────────── + Time Allocations + ─────────────────────── ──────────────────────── + Tot / % measured: 61.4ms / 99.2% 5.60MiB / 99.6% + + Section ncalls time %tot avg alloc %tot avg + ─────────────────────────────────────────────────────────────────────── + test timer 2 60.9ms 100.0% 60.9ms 5.57MiB 100.0% 5.57MiB + ─────────────────────────────────────────────────────────────────────── + """ + # Remove "Tot / % measured" line and trailing white spaces and replace + # the "test timer" line (but don't remove it, we want to check that it's there). + expected = replace(timer_output, r"Tot / % measured: .*" => "", + r"\s+\n" => "\n", + r"test timer 2 .*B\n" => "test timer 2") + actual = replace(repr(timer()) * "\n", r"Tot / % measured: .*" => "", + r"\s+\n" => "\n", + r"test timer 2 .*B\n" => "test timer 2") + + # Compare against empty timer output + @test actual == expected + end +end; diff --git a/test/trixi_include.jl b/test/trixi_include.jl index fb243d6..379e721 100644 --- a/test/trixi_include.jl +++ b/test/trixi_include.jl @@ -1,4 +1,4 @@ -@testset "trixi_include" begin +@testset verbose=true "`trixi_include`" begin @trixi_testset "Basic" begin example = """ x = 4