Add timer() and @trixi_timeit (#25)

* Add `timer()` and `@trixi_timeit`

* Add tests

* Add tests for enabling and disabling timings

* Increment version number

* Implement suggestions

* Fix tests

* Update src/trixi_timeit.jl

Co-authored-by: Hendrik Ranocha <[email protected]>

* Update src/trixi_timeit.jl

Co-authored-by: Hendrik Ranocha <[email protected]>

* Update src/trixi_timeit.jl

Co-authored-by: Hendrik Ranocha <[email protected]>

* Update src/trixi_timeit.jl

Co-authored-by: Hendrik Ranocha <[email protected]>

---------

Co-authored-by: Hendrik Ranocha <[email protected]>

Project.toml

@@ -1,7 +1,10 @@
 name = "TrixiBase"
 uuid = "9a0f1c46-06d5-4909-a5a3-ce25d3fa3284"
 authors = ["Michael Schlottke-Lakemper <[email protected]>"]
-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]

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})

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

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;

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;

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
 
 """

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