Dummy timers as a zero-overhead alternative to @timeit_debug

[jipolanco]

First of all, thanks again for this really useful package.

I'd like to propose an alternative zero-overhead mechanism for disabling timers, which avoids some of the issues with the @timeit_debug macro (see for example #61, maybe #105?). More practically, it also provides a very convenient way of enabling and disabling timers (in my opinion).

The idea is simple: define a dummy type, that I have called NoTimerOutput (but this can be changed...), that works as a direct replacement for a TimerOutput. In other words, to disable timings in their code, a user would just need to switch from a real TimerOutput to a dummy timer.

I've checked that the proposed implementation disables timings and has zero overhead. This also includes the case of annotated functions (as in @timeit to f(to) = 3). See below for some examples, which were run on Julia 1.6-rc3.

using TimerOutputs
using BenchmarkTools
using LinearAlgebra

to = TimerOutput()
nt = NoTimerOutput()

A = rand(20, 20)

In this first example, NoTimerOutput has zero overhead, just like @timeit_debug:

@btime norm($A)                           # 156.195 ns (0 allocations: 0 bytes)
@btime @timeit $to "norm" norm($A)        # 273.036 ns (0 allocations: 0 bytes)
@btime @timeit_debug $to "norm" norm($A)  # 156.285 ns (0 allocations: 0 bytes)
@btime @timeit $nt "norm" norm($A)        # 156.289 ns (0 allocations: 0 bytes)

Second example using function annotations, based on #61. Note that, as discussed in #61, @timeit_debug has always some overhead. On the other hand, passing a NoTimerOutput to @timeit has zero overhead:

@timeit tt function make_zeros(tt)
    dims = (3, 4)
    zeros(dims)
end

@timeit_debug tt function make_zeros_debug(tt)
    dims = (3, 4)
    zeros(dims)
end

@btime zeros(dims) setup=(dims = (3, 4))  # 38.435 ns (1 allocation: 176 bytes)
@btime make_zeros($to)                    # 160.159 ns (1 allocation: 176 bytes)
@btime make_zeros($nt)                    # 38.547 ns (1 allocation: 176 bytes)
@btime make_zeros_debug($to)              # 52.505 ns (1 allocation: 176 bytes)
@btime make_zeros_debug($nt)              # 51.761 ns (1 allocation: 176 bytes)

This PR is work in progress, as it's still missing tests as well as some documentation on its usage. To make it fully compatible with TimerOutput, it may also need some dummy definitions for getindex, flatten, complement!, and other documented functions.

[KristofferC]

It's an interesting proposal, but from what I understand it lacks the flexibility of being able to enable/disable the timers in various other packages where going in and changing the source code is not feasible.

Regarding the bad performance with @timeit_debug, I actually think this is mostly a problem with the current implementation. As I wrote here: #61 (comment), the duplication of the body in the function is not ideal. At least for the @timeit_debug "foo" function() .... syntax, it shouldn't be too hard to fix. Slightly harder when the annotation is already inside the body of a function.

[jipolanco]

It's an interesting proposal, but from what I understand it lacks the flexibility of being able to enable/disable the timers in various other packages where going in and changing the source code is not feasible.

Well, that depends on how timers are used within packages using TimerOutputs.

My logic is that a package should allow the user to pass their own TimerOutput instances. This is something that I've been doing for a while in my own packages (see for instance this constructor, which takes an optional TimerOutput).

Following this logic, it would be enough to pass around a dummy TimerOutput-like object to fully disable timers. For the user, it's just a single switch in their code.

[KristofferC]

My logic is that a package should allow the user to pass their own TimerOutput instances.

I see, that is pretty clean and would work well with this PR, indeed. Just to be clear, I'm fine putting something like this in but I just wanted to note that I think we can still do better with the existing @timeit_debug. Just haven't gotten around to putting a concentrated effort into it (since I don't really use it myself).

[jipolanco]

Great, thanks. I'll put some more work on this PR and let you know when it's ready.

In any case, this proposal doesn't interfere with @timeit_debug and is not meant to replace it. It would be very nice indeed if such improvements were made to @timeit_debug.

[jipolanco]

This is ready for review.

[KristofferC]

Hm, It is slightly unfortunate to have to insert the full expression here again. It would probable be removed by the compiler early because it knows isdummy on compile time but perhaps it could be posible to exploit dispatch a bit better with something like:

function enter_section(::TimerOutput)
    accumulated_data = $(push!)(to, $(esc(label)))
    return accumulated_data, gc_bytes(), time_ns()
end
enter_section(::NoTimerOutput) = nothing 

function exit_section(::TimerOutput, data) = 
    if enabled
        do_accumulate!(
   ...
exit_section(::NoTimerOutput, data::Nothing) = nothing

and then have the macro expand to

local data = enter_section!(to)
local val
$(Expr(:tryfinally,
   ....
)
exit_section!(to, data)

[jipolanco]

I thought about doing something like that, but there is one small issue: the try/finally block is always compiled and executed. This adds some overhead, which I agree is really small (~10 ns), but breaks the zero-overhead promise. As you noticed, this is not an issue with the current implementation, as the try/finally block is optimised away by the compiler. But I agree that it's not very elegant to copy the whole expression twice...

[fredrikekre]

(Alternative name could be NullTimer (to mirror NullLogger for example))

[jipolanco]

(Alternative name could be NullTimer (to mirror NullLogger for example))

I agree, that's a good suggestion. Maybe NullTimerOutput to avoid potential ambiguities?

[jlchan]

Any update on this PR? FWIW, NullTimer was exactly what I was looking for in my workflow.

[jipolanco]

I just rebased to the current master.

A single test fails, in which the TimerOutputs symbol is not explicitly loaded, and therefore the isdummy function is not visible.

A very hacky workaround, which seems to work, is to replace this line by:

        # if TimerOutputs.isdummy($local_to)  # current version
        if Main.hasfield(typeof($local_to), :enabled) === false
            return $ex
        end

[jlchan]

@jipolanco I noticed an odd issue where using a NullTimer changed my code behavior. I'll see if I can produce a MWE.

Is the "hacky workaround" implemented in your branch already?

[jlchan]

Here's an MWE for the issue using this PR. NullTimer seems to cause the function to skip some parts of the code.

using TimerOutputs,UnPack,Test

function foo!(dx,x,timer)    
    @timeit timer "set x" begin            
        x .= 2.0         
    end
    @timeit timer "set dx" begin            
        dx .= x
    end    
    return nothing
end

timer = NullTimer()     # fails for NullTimer
# timer = TimerOutput()   # passes for regular TimerOutput

x = zeros(2)
dx = similar(x)
foo!(dx,x,timer)
@test all(dx .≈ 2.0)

[jipolanco]

@jlchan Thanks for noticing that issue! I just pushed a possible fix.

[jlchan]

Works great for my examples - thanks!

[jlchan]

Bumping - any outstanding issues remaining with this PR?