From f42854f6afeb391130833a6f1ba09eded786c06a Mon Sep 17 00:00:00 2001 From: Erik Faulhaber <44124897+efaulhaber@users.noreply.github.com> Date: Fri, 7 Jun 2024 13:04:42 +0200 Subject: [PATCH 01/10] Add `timer()` and `@trixi_timeit` --- Project.toml | 4 ++++ src/TrixiBase.jl | 4 ++++ src/trixi_timeit.jl | 43 +++++++++++++++++++++++++++++++++++++++++++ 3 files changed, 51 insertions(+) create mode 100644 src/trixi_timeit.jl 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 From 2ac2256e53c8af15c291f7b4791154c4c39ae6a3 Mon Sep 17 00:00:00 2001 From: Erik Faulhaber <44124897+efaulhaber@users.noreply.github.com> Date: Fri, 7 Jun 2024 13:45:39 +0200 Subject: [PATCH 02/10] Add tests --- test/runtests.jl | 3 ++- test/test_timers.jl | 59 +++++++++++++++++++++++++++++++++++++++++++ test/trixi_include.jl | 2 +- 3 files changed, 62 insertions(+), 2 deletions(-) create mode 100644 test/test_timers.jl 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 From e4c912dd762161a739c1768e15823d34f7d7abf4 Mon Sep 17 00:00:00 2001 From: Erik Faulhaber <44124897+efaulhaber@users.noreply.github.com> Date: Fri, 7 Jun 2024 13:56:21 +0200 Subject: [PATCH 03/10] Add tests for enabling and disabling timings --- src/TrixiBase.jl | 3 ++- test/test_timers.jl | 43 +++++++++++++++++++++++++++++++++++++++++++ 2 files changed, 45 insertions(+), 1 deletion(-) diff --git a/src/TrixiBase.jl b/src/TrixiBase.jl index c4829fa..daac03c 100644 --- a/src/TrixiBase.jl +++ b/src/TrixiBase.jl @@ -6,7 +6,8 @@ include("trixi_include.jl") include("trixi_timeit.jl") export trixi_include -export @trixi_timeit, timer, timeit_debug_enabled, disable_debug_timings +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/test/test_timers.jl b/test/test_timers.jl index 9438c72..38bef8e 100644 --- a/test/test_timers.jl +++ b/test/test_timers.jl @@ -56,4 +56,47 @@ # 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; From 5739347abc13e44bc55d23de9a09f19376d741dd Mon Sep 17 00:00:00 2001 From: Erik Faulhaber <44124897+efaulhaber@users.noreply.github.com> Date: Fri, 7 Jun 2024 14:12:04 +0200 Subject: [PATCH 04/10] Increment version number --- Project.toml | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/Project.toml b/Project.toml index 66d0c4c..0a20452 100644 --- a/Project.toml +++ b/Project.toml @@ -1,7 +1,7 @@ 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" From e790d4cc8ded42456cda3be3fd4a8760b16425cc Mon Sep 17 00:00:00 2001 From: Erik Faulhaber <44124897+efaulhaber@users.noreply.github.com> Date: Mon, 10 Jun 2024 10:46:03 +0200 Subject: [PATCH 05/10] Implement suggestions --- src/trixi_timeit.jl | 50 +++++++++++++++++++++++++++++++++++---------- test/test_timers.jl | 2 +- 2 files changed, 40 insertions(+), 12 deletions(-) diff --git a/src/trixi_timeit.jl b/src/trixi_timeit.jl index 15883db..d27eb45 100644 --- a/src/trixi_timeit.jl +++ b/src/trixi_timeit.jl @@ -4,24 +4,52 @@ # and to enable them again by executing # `TimerOutputs.enable_debug_timings(TrixiBase)` timeit_debug_enabled() = true + +""" + disable_debug_timings() + +Disable all `@trixi_timeit` and `@timeit_debug` 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` and `@timeit_debug` timings. + +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 +# Store main timer for global timing of functions. +# Always call timer() to hide implementation details. const main_timer = TimerOutput() -# Always call timer() to hide implementation details +""" + timer() + +Main timer for global timing. +""" 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). +""" + @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. + +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() diff --git a/test/test_timers.jl b/test/test_timers.jl index 38bef8e..70f9a3f 100644 --- a/test/test_timers.jl +++ b/test/test_timers.jl @@ -1,6 +1,6 @@ @testset verbose=true "Timers" begin @testset verbose=true "`timer()`" begin - @test timer() isa TrixiBase.TimerOutput + @test (@inferred timer()) isa TrixiBase.TimerOutput # Test empty timer output TrixiBase.TimerOutputs.reset_timer!(timer()) From c81f5cee5c3a381c70998b30395e96e5028a2e54 Mon Sep 17 00:00:00 2001 From: Erik Faulhaber <44124897+efaulhaber@users.noreply.github.com> Date: Mon, 10 Jun 2024 10:55:23 +0200 Subject: [PATCH 06/10] Fix tests --- test/test_util.jl | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) 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 """ From 42077943d7733c7edbb770784a5962f013b002db Mon Sep 17 00:00:00 2001 From: Erik Faulhaber <44124897+efaulhaber@users.noreply.github.com> Date: Mon, 10 Jun 2024 17:06:03 +0200 Subject: [PATCH 07/10] Update src/trixi_timeit.jl Co-authored-by: Hendrik Ranocha --- src/trixi_timeit.jl | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/src/trixi_timeit.jl b/src/trixi_timeit.jl index d27eb45..53251c8 100644 --- a/src/trixi_timeit.jl +++ b/src/trixi_timeit.jl @@ -8,7 +8,7 @@ timeit_debug_enabled() = true """ disable_debug_timings() -Disable all `@trixi_timeit` and `@timeit_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). From 525eaa8d80f35eb9bc3a5dddca0e266b02ec5d51 Mon Sep 17 00:00:00 2001 From: Erik Faulhaber <44124897+efaulhaber@users.noreply.github.com> Date: Mon, 10 Jun 2024 17:06:08 +0200 Subject: [PATCH 08/10] Update src/trixi_timeit.jl Co-authored-by: Hendrik Ranocha --- src/trixi_timeit.jl | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/src/trixi_timeit.jl b/src/trixi_timeit.jl index 53251c8..de7d692 100644 --- a/src/trixi_timeit.jl +++ b/src/trixi_timeit.jl @@ -19,7 +19,7 @@ disable_debug_timings() = TimerOutputs.disable_debug_timings(@__MODULE__) """ enable_debug_timings() -Enable all `@trixi_timeit` and `@timeit_debug` timings. +Enable all [`@trixi_timeit`](@ref) timings (default behavior). See also [`disable_debug_timings`](@ref), [`@trixi_timeit`](@ref). """ From 6dbd20bdcd4ff3145c6f3ed37f814d42d847544e Mon Sep 17 00:00:00 2001 From: Erik Faulhaber <44124897+efaulhaber@users.noreply.github.com> Date: Mon, 10 Jun 2024 17:06:13 +0200 Subject: [PATCH 09/10] Update src/trixi_timeit.jl Co-authored-by: Hendrik Ranocha --- src/trixi_timeit.jl | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/src/trixi_timeit.jl b/src/trixi_timeit.jl index de7d692..17979f5 100644 --- a/src/trixi_timeit.jl +++ b/src/trixi_timeit.jl @@ -32,7 +32,7 @@ const main_timer = TimerOutput() """ timer() -Main timer for global timing. +Main timer for global timing, e.g., to be used with [`@trixi_timeit`](@ref). """ timer() = main_timer From e2894f38f48b8e0f219fc7c269e28f89148e532f Mon Sep 17 00:00:00 2001 From: Erik Faulhaber <44124897+efaulhaber@users.noreply.github.com> Date: Mon, 10 Jun 2024 17:06:18 +0200 Subject: [PATCH 10/10] Update src/trixi_timeit.jl Co-authored-by: Hendrik Ranocha --- src/trixi_timeit.jl | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/src/trixi_timeit.jl b/src/trixi_timeit.jl index 17979f5..d379c46 100644 --- a/src/trixi_timeit.jl +++ b/src/trixi_timeit.jl @@ -43,7 +43,7 @@ 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. +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.