Adding a macro for timed testsets?

[oschulz]

We're currently debugging the very long test/CI time of SolidStateDetectors.jl. Since it's a numerical package it has to run a lot of calculations during CI to check if it's working correctly, but we've definitely reached a point where we need to cut it down at least a bit, and so we need a clear picture of where most of the test time is spent. TimerOutputs is so handy here (thanks @KristofferC ! ).

I ended up writing a macro

testtimer() = get_timer("_default_testtimer_")

macro timed_testset(title, body)
    quote
        tmr = testtimer()
        _title = $(esc(title))
        @timeit tmr "$_title" begin
            @testset "$_title" begin
                $(esc(body))
            end
        end
    end
end

So one can simple replace @testset by @timed_testset in the test code and get something like

@timed_testset "a" begin
    @timed_testset "a.1" begin
        @test (sleep(1); true)
    end
    @timed_testset "a.2" begin
        @test (sleep(1); true)
    end
end

@timed_testset "b" begin
    @timed_testset "b.1" begin
        @test (sleep(1); true)
    end
    @timed_testset "b.2" begin
        @test (sleep(1); true)
    end
end

and then just insert display(testtimer()) at the end of "runtests.jl" to add the result

 ──────────────────────────────────────────────────────────────────────────────
                                      Time                    Allocations      
                             ───────────────────────   ────────────────────────
      Tot / % measured:           22.1s /  19.8%           30.8MiB /  34.4%    

 Section             ncalls     time    %tot     avg     alloc    %tot      avg
 ──────────────────────────────────────────────────────────────────────────────
 a                        1    2.35s   53.9%   2.35s   10.6MiB   99.8%  10.6MiB
   a.1                    1    1.08s   24.6%   1.08s    639KiB    5.9%   639KiB
   a.2                    1    1.01s   23.1%   1.01s   2.33KiB    0.0%  2.33KiB
 b                        1    2.01s   46.1%   2.01s   20.6KiB    0.2%  20.6KiB
   b.2                    1    1.01s   23.1%   1.01s   2.33KiB    0.0%  2.33KiB
   b.1                    1    1.00s   23.0%   1.00s   2.41KiB    0.0%  2.41KiB
 ──────────────────────────────────────────────────────────────────────────────

to the CI output. I think this could be very useful in general - could we add such a macro to TimerOutputs.jl (I could prep a PR)?