Macro for counting the number of times a function is called?

Dear All,

I’m trying to count the number of times a function is called; rather than assign a global variable by hand inside each function, it makes sense to use a macro. The instrumenting profiler can do this, but it seems overkill for what I want. Any tips on how best to do this?

Best
Simon

1 Like

Try this:

const COUNTERS = Dict{String, Int}()

macro counted(f)
    name = f.args[1].args[1]
    name_str = String(name)
    body = f.args[2]
    counter_code = quote
        if !haskey(COUNTERS, $name_str)
            COUNTERS[$name_str] = 0
        end
        COUNTERS[$name_str] += 1
    end
    insert!(body.args, 1, counter_code)
    return f
end

@counted inc(x) = x + 1

inc(5)
inc(42)
inc(18)

COUNTERS["inc"]  # ==> 3
2 Likes

And a non-macro solution:

type Counting{TF}
    f::TF
    counter::Int
end

Counting(f) = Counting(f, 0)

function (c::Counting)(args...)
    c.counter += 1
    c.f(args...)
end

cf = Counting(identity)

[cf(i) for i in 1:10]

cf.counter
6 Likes

@Tamas_Papp nice solution!
I’d add one minor thing, to underline the fact that you can use this like the real function with almost no downsides:

type Counting{TF} <: Function # inherit from function, to integrate better with e.g. map
    f::TF
    counter::Int
end
# Define the function you want to count like this:
const my_function = Counting() do args...
  # my function body
end
# use as like any other julia function
map(my_function, rand(10))
1 Like

GitHub - KristofferC/TimerOutputs.jl: Formatted output of timed sections in Julia can do this but perhaps it is overkill for this situation.

You don’t need to make the type <: Function to work with map. Cf a question I asked recently:

1 Like

Yeah map is a bad example, since it’s actually not typed that way… But there are definitely other functions where that’d be the case

@kristoffer.carlsson That sounds like a powerful solution but how do you do it generically? I’m trying to do something like

const timer = TimerOutput()
for fun in (:f, :g, :h)
  fname = Symbol("timed_$(fun)")
  @eval $(fname)(args...) = :(@timeit timer string($(fun)) $fun(args...))
end

but it’s not quite right. Thanks!

julia> using TimerOutputs

julia> const timer = TimerOutput();

julia> for fun in (:f, :g, :h)
              fname = Symbol("timed_$(fun)")
              @eval $(fname)(args...) = @timeit timer string($(fun)) $fun(args...)
          end

julia> f(x) = x
f (generic function with 1 method)

julia> timed_f(2)
2

julia> timer
 ──────────────────────────────────────────────────────────────────
                           Time                   Allocations      
                   ──────────────────────   ───────────────────────
 Tot / % measured:      2.89s / 0.05%           11.8MiB / 0.01%    

 Section   ncalls     time   %tot     avg     alloc   %tot      avg
 ──────────────────────────────────────────────────────────────────
 f              1   1.38ms   100%  1.38ms         -  100%         -
 ──────────────────────────────────────────────────────────────────
2 Likes

Yes, that works, thank you. The extra quote level was because I was fiddling to get something like this to work:

type Thing
  fs::Vector{Function}
  timer::TimerOutput
end

function Thing(funs::Symbol...)
  timed_funs = Function[]
  timer = TimerOutput()
  for fun in funs
    fname = Symbol("timed_$(fun)")
    @eval begin
      $(fname)(args...) = @timeit timer string($(fun)) $fun(args...)
      push!($(timed_funs), $(fname))
    end
  end
  return Thing(timed_funs, timer)
end

Somehow, the timed functions have lost track of timer:

julia> f(x) = x; g(x) = x+1; h(x) = x+2;

julia> thing = Thing(:f, :g, :h);

julia> [f(1) for f in thing.fs]
ERROR: UndefVarError: timer not defined

I’d rather not pass timer as argument to the constructor because I’d like to have several Things, each with its own timer.
I must be confused. I guess @timeit doesn’t quite behave like a closure?!

@eval is done in global scope so it won’t have access to local variables.

1 Like

Is a macro the only way to achieve what I’m trying to do then?

My thinking is if you want to have a function reference a global variable you need to make the variable global.

So perhaps something like:

function Thing(funs::Symbol...)
  timed_funs = Function[]
  timerlabel = gensym()
  @eval const $timerlabel = TimerOutput()
  for fun in funs
    fname = Symbol("timed_$(fun)")
    @eval begin
      $(fname)(args...) = @timeit $(timerlabel) string($(fun)) $fun(args...)
      push!($(timed_funs), $(fname))
    end
  end
  return Thing(timed_funs, @eval $timerlabel)
end

giving

julia> f(x) = x; g(x) = x+1; h(x) = x+2;

julia> thing = Thing(:f, :g, :h);

julia> [f(1) for f in thing.fs]
3-element Array{Int64,1}:
 1
 2
 3

julia> thing.timer
 ──────────────────────────────────────────────────────────────────
                           Time                   Allocations      
                   ──────────────────────   ───────────────────────
 Tot / % measured:      8.54s / 0.05%           14.0MiB / 0.02%    

 Section   ncalls     time   %tot     avg     alloc   %tot      avg
 ──────────────────────────────────────────────────────────────────
 h              1   1.57ms  33.8%  1.57ms         -  35.2%        -
 g              1   1.56ms  33.6%  1.56ms         -  35.2%        -
 f              1   1.51ms  32.6%  1.51ms         -  29.7%        -
 ──────────────────────────────────────────────────────────────────
1 Like

Note that if you want to timer to be exception safe you should use the do format:

timeit(to, "label") do
    # stuff
end

(will be slightly slower due to try catching)

1 Like

Is this the right way to avoid global variables then?

julia> using TimerOutputs

julia> type Thing
       fs::Vector{Function}
       timer::TimerOutput
       end

julia> function Thing(fs::Function...)
       timer = TimerOutput()
       return Thing([(args...) -> @timeit timer "f" f(args...) for f in fs], timer)
       end
Thing

julia> f(x) = x; g(x) = x+1; h(x) = x+2;

julia> thing = Thing(f, g, h);

julia> [f(1) for f in thing.fs]
3-element Array{Int64,1}:
 1
 2
 3

julia> thing.timer
 ──────────────────────────────────────────────────────────────────
                           Time                   Allocations      
                   ──────────────────────   ───────────────────────
 Tot / % measured:      18.9s / 0.02%           93.6MiB / 0.00%    

 Section   ncalls     time   %tot     avg     alloc   %tot      avg
 ──────────────────────────────────────────────────────────────────
 f              3   3.53ms   100%  1.18ms   1.41KiB  100%         -
 ──────────────────────────────────────────────────────────────────
1 Like

Yeah, storing a closure also works.

Thank you!

I followed the instructions of the package but I could not get it to work. I want to track the number of function calls.

The function is defined inside a module and is being used by a variety of other modules. I am able to modify the code inside the module.

example code of my trial:

module MyModule 
const to = TimerOutput()

function myFunc()
    @timeit to "myFunc" begin 
        #normal computation of myFunc()
    end 
    return 
end

end

# code that uses other modules that use MyModule #

show(MyModule.to)

and the output is empty even though it counts time and allocations:

 ────────────────────────────────────────────────────────────────────
                            Time                    Allocations      
                   ───────────────────────   ────────────────────────
 Tot / % measured:      13.1s /   0.0%           1.48GiB /   0.0%    

 Section   ncalls     time    %tot     avg     alloc    %tot      avg
 ────────────────────────────────────────────────────────────────────
 ────────────────────────────────────────────────────────────────────
module MyModule 

using TimerOutputs
const to = TimerOutput()

function myFunc()
    @timeit to "myFunc" begin 
        sleep(0.00001)
    end 
    return 
end

end

using TimerOutputs
TimerOutputs.reset_timer!(MyModule.to)

for i in 1:100
    MyModule.myFunc()
end

show(MyModule.to)

Result:

julia> show(MyModule.to)
 ────────────────────────────────────────────────────────────────────
                            Time                    Allocations
                   ───────────────────────   ────────────────────────
 Tot / % measured:      686ms /  33.3%            654KiB /   2.3%

 Section   ncalls     time    %tot     avg     alloc    %tot      avg
 ────────────────────────────────────────────────────────────────────
 myFunc       100    229ms  100.0%  2.29ms   15.2KiB  100.0%     156B
3 Likes