Using macros to implement function decorators for logging / measuring time

General Usage
,
1

Hi All,

I’m trying to implement something like Python’s decorators so that I can log whenever a function get’s called (eventually I want to log execution time / exceptions / etc)

This is the API I’d like to have:

@log_calls function foo(a, b,c)
  ...
end

and whenever foo is called, it will log “calling foo” and “called foo” when it’s done.

I though that would be a good use of a macro, and this is something I found and modified a bit:

 macro log_calls(func)
     name = func.args[1].args[1]
     hiddenname = gensym()
     func.args[1].args[1] = hiddenname

     _decorator(f) = (args...) -> begin
         @info "calling $(name)"
         f(args...)
         @info "called $(name)"
     end

     quote
         $func
         $(esc(name)) = $_decorator($hiddenname)
     end
 end

This works when used from the same module it get’s called, but I’d like to put it in some Utils module, but then it breaks because it seems it tries to define func in the scope of the Utils module so I get undefined variables errors.

Is it possible to do that in Julia?
What am I missing?

Thanks.

2

You need to properly escape the expression you return, see Metaprogramming · The Julia Language.

It might also be easier to just splice in the loggin calls in the original expression instead of creating a wrapper function.

3

This does work inside a module, for me. With a bit more printing & returning the returned value:

module Mod

macro log_calls(func)
    name = func.args[1].args[1]
    hiddenname = gensym()
    func.args[1].args[1] = hiddenname
    @info "decorating $name" hiddenname

    _decorator(f) = (args...) -> begin
        @info "calling $(name)"
        ret = f(args...)
        @info "called $(name)"
        ret
    end

    quote
        $func
        $(esc(name)) = $_decorator($hiddenname)
    end
end

end  # module

using .Mod

Mod.@log_calls g(x::Int) = "gee! $x" 

g(33)

Mod.@log_calls g(x::String) = "got a string: $x" 

g("three")

g(33) # MethodError

isconst(Main, :g) # false

One thing this doesn’t do is to let you add methods to an existing function. As fredrikekre suggests, altering the body of the given function definition to splice in some extra commands might be a better solution.

4

Thanks for your replies!

I should have added a better example.


using Mod

struct Foo
    a::Int
end


#this works
@log_calls function hey(a)
    print("here is a: $(a)")
end


#this doesn't works
@log_calls function foo(f::Foo)
    print("here is a: $(f.a)")
end

running this, I get the following exception

┌ Info: decorating hey
└   hiddenname = Symbol("##422")
┌ Info: decorating foo
└   hiddenname = Symbol("##423")
ERROR: LoadError: UndefVarError: Foo not defined
Stacktrace:
 [1] top-level scope at /Users/quatrix/workspace/misc/julia_decorator/Mod.jl:19
 [2] include at ./boot.jl:328 [inlined]
 [3] include_relative(::Module, ::String) at ./loading.jl:1105
 [4] include(::Module, ::String) at ./Base.jl:31
 [5] exec_options(::Base.JLOptions) at ./client.jl:287
 [6] _start() at ./client.jl:460
in expression starting at /Users/quatrix/workspace/misc/julia_decorator/main.jl:17
5

Oh right, func also needs to be escaped. This is one way, just do everything in the caller’s scope, since you don’t introduce any symbols besides the generated hiddenname :

    quote
        $func
        $name = $_decorator($hiddenname)
    end |>esc
6

Thanks! this works!

It’s really too bad this doesn’t let adding methods to an existing function, is there a way to implement this without assigning to a $name variable?

As you see it’s currently beyond my macro skills, but is it possible to take the name and the body the function this macro wraps, and create a new function with same name and arguments in the scope of the current module?

7

Yes you can just add things into the given expression, without altering its name at all, and then let it be evaluated as before:

ex = :(function f(x) 123; 456; end)
dump(ex)
pushfirst!(ex.args[2].args, :( @show "hi" ))
@eval $ex
f(0)

However I think it can get a bit thorny dealing with every valid way to define a function. (I think that GitHub - invenia/ExprTools.jl: Light-weight expression manipulation tools is meant to handle such things, but have not used it.)

2 Likes
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