Using macros to implement function decorators for logging / measuring time

General Usage
,
8

Something like the following should work. Note that, as advised by @mcabbott, using ExprTools greatly simplifies the work with function definitions in macros.

This works in the same way as the above, except that instead of altering the existing body, it generates another one by wrapping it inside a new begin...end block.

module LogCalls

using ExprTools # splitdef, combinedef

macro log_calls(defun)
    def = splitdef(defun)
    name = def[:name]
    body = def[:body]

    # $name is interpolated in the strings, which will be
    # interpolated into the generated expression
    # => it's easier to do this in two steps
    enter = "calling $name"
    leave = "called $name"

    # Surround the original body with @info messages
    def[:body] = quote
        @info $enter
        $body
        @info $leave
    end

    # Recombine the function definition and output it (escaped!)
    esc(combinedef(def))
end

end

Macro expansion test:

julia> @macroexpand1 LogCalls.@log_calls function foo(f::Foo)
           println("here is a: $(f.a)")
       end
:(function foo(f::Foo)
      #= REPL[1]:13 =#
      #= REPL[1]:13 =# @info "calling foo"
      #= REPL[1]:14 =#
      begin
          #= REPL[2]:2 =#
          println("here is a: $(f.a)")
      end
      #= REPL[1]:15 =#
      #= REPL[1]:15 =# @info "called foo"
  end)

Example use:

julia> struct Foo
           a::Int
       end

julia> import .LogCalls

julia> LogCalls.@log_calls function foo(f::Foo)
           println("here is a: $(f.a)")
       end
foo (generic function with 1 method)

julia> f = Foo(42)
Foo(42)

julia> foo(f)
[ Info: calling foo
here is a: 42
[ Info: called foo
2 Likes