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


#1

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


What variable runtime values can be accessed in compile time (macro expansion)?
#2

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

#3

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

#4

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

#5

https://github.com/KristofferC/TimerOutputs.jl can do this but perhaps it is overkill for this situation.


#6

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


#7

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


#8

@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!


#9
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%         -
 ──────────────────────────────────────────────────────────────────

#10

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?!


#11

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


#12

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


#13

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%        -
 ──────────────────────────────────────────────────────────────────

#14

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)


#15

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%         -
 ──────────────────────────────────────────────────────────────────

#16

Yeah, storing a closure also works.


#17

Thank you!