diff --git a/Project.toml b/Project.toml index fb13a3c..0a20452 100644 --- a/Project.toml +++ b/Project.toml @@ -1,7 +1,10 @@ name = "TrixiBase" uuid = "9a0f1c46-06d5-4909-a5a3-ce25d3fa3284" authors = ["Michael Schlottke-Lakemper "] -version = "0.1.3-pre" +version = "0.1.3" + +[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..daac03c 100644 --- a/src/TrixiBase.jl +++ b/src/TrixiBase.jl @@ -1,8 +1,13 @@ 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, enable_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..d379c46 --- /dev/null +++ b/src/trixi_timeit.jl @@ -0,0 +1,71 @@ +# 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() + +Disable all [`@trixi_timeit`](@ref) timings. +The timings should be optimized away, allowing for truly zero-overhead. +Enable timings again with [`enable_debug_timings`](@ref). + +See also [`enable_debug_timings`](@ref), [`@trixi_timeit`](@ref). +""" +disable_debug_timings() = TimerOutputs.disable_debug_timings(@__MODULE__) + +""" + enable_debug_timings() + +Enable all [`@trixi_timeit`](@ref) timings (default behavior). + +See also [`disable_debug_timings`](@ref), [`@trixi_timeit`](@ref). +""" +enable_debug_timings() = TimerOutputs.enable_debug_timings(@__MODULE__) + +# Store main timer for global timing of functions. +# Always call timer() to hide implementation details. +const main_timer = TimerOutput() + +""" + timer() + +Main timer for global timing, e.g., to be used with [`@trixi_timeit`](@ref). +""" +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.jl, that's not really an issue. + +All `@trixi_timeit` timings can be disabled with [`disable_debug_timings`](@ref). +The timings should then be optimized away, allowing for truly zero-overhead. + +See also [`disable_debug_timings`](@ref), [`enable_debug_timings`](@ref). +""" +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..70f9a3f --- /dev/null +++ b/test/test_timers.jl @@ -0,0 +1,102 @@ +@testset verbose=true "Timers" begin + @testset verbose=true "`timer()`" begin + @test (@inferred 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 + + @testset verbose=true "disable and enable timings" begin + # Start with empty timer output + TrixiBase.TimerOutputs.reset_timer!(timer()) + + # Disable timings + disable_debug_timings() + + # These two timings should be disabled + @trixi_timeit timer() "test timer" sin(0.0) + @trixi_timeit timer() "test timer" sin(0.0) + + # Disable timings + enable_debug_timings() + + # This timing should be counted + @trixi_timeit timer() "test timer 2" sin(0.0) + + println(timer()) + + timer_output = """ + ───────────────────────────────────────────────────────────────────────── + Time Allocations + ─────────────────────── ──────────────────────── + Tot / % measured: 23.7ms / 0.0% 1.00MiB / 0.0% + + Section ncalls time %tot avg alloc %tot avg + ───────────────────────────────────────────────────────────────────────── + test timer 2 1 875ns 100.0% 875ns 48.0B 100.0% 48.0B + ───────────────────────────────────────────────────────────────────────── + """ + # 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 1 .*B\n" => "test timer 2 1") + actual = replace(repr(timer()) * "\n", r"Tot / % measured: .*" => "", + r"\s+\n" => "\n", + r"test timer 2 1 .*B\n" => "test timer 2 1") + + # Compare against empty timer output + @test actual == expected + end +end; diff --git a/test/test_util.jl b/test/test_util.jl index 4130cfa..18443f5 100644 --- a/test/test_util.jl +++ b/test/test_util.jl @@ -1,6 +1,6 @@ # All `using` calls are in this file, so that one can run any test file # after running only this file. -using Test: @test, @testset +using Test: @test, @testset, @inferred using TrixiBase """ 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