Trying to write a macro that will cause a function to be traced

General Usage
1

I want to be able to conitionally trace some of my methods, that is, to log the arguments and return values of each invocation.

For example, given this function definition

function hanoi(from, to, other, count)
    if count == 1
        println("move 1 from $from to $to")
        return
    else
        hanoi(from, other, to, count - 1)
        println("move 1 from $from to $to")
        hanoi(other, to, from, count - 1)
        return (from, to)   # arbitrary result to show
    end
end

how would I write a macro that, when applied to that definition, redefines the function as

function hanoi(from, to, other, count)
    function var"##bodyfunction#258"()
        # This is just the body of the original function:
        if count == 1
            println("move 1 from $from to $to")
            return
        else
            hanoi(from, other, to, count - 1)
            println("move 1 from $from to $to")
            hanoi(other, to, from, count - 1)
            return (from, to)   # arbitrary result to show
        end
        # end of original function body.
    end
    # Consitionaly log the function call.  The name of the variable
    # `trace_hanoi` will be a parameter of the macro:
    if trace_hanoi
        @info("Trace enter", call = Expr(:call, hanoi, from, to, other, count))
    end
    var"##result#259" = var"##bodyfunction#258"()
    # Conditionally log the function's return value:
    if trace_hanoi
        @info("Trace exit", result = var"##result#259")
    end
    var"##result#259"
end

I have a partial inplementation at NahaJuliaLib.jl/src/trace.jl at 1c4f9665d0906121998bcc14b7637c6824464a8b · MarkNahabedian/NahaJuliaLib.jl · GitHub (appologies for the obvious flailing about).

The root of my problem is intercolating the values of the function arguments, rather than their names, in the “Trace enter” call expression.

I tries asking something similar but didn’t get any response, I suspect because the topic was not descriptive. I hope the lack of response wan’t because there isn’t a way to do this in JUlia.

Thanks.

2

I’ve reduced the scope a bit, but I think this solves the core of what you’re trying to do:

using MacroTools: @capture

macro trace(expr)
    ok = @capture(expr, function f_(args__)
            body__
            end)
    ok || error("Could not parse function definition")
    
    quote
        function $(esc(f))($(esc.(args)...))
            function inner($(esc.(args)...))
                $(esc.(body)...)
            end
            
            println("You called ", $f, 
                 " with arguments: ", join(($(esc.(args)...),), ' '))
            result = inner($(esc.(args)...))
            println("and you got ", result)
            return result
        end
    end
end

Usage:

julia> @trace function foo(x, y)
           z = x + y
           return 2 * z
       end
foo (generic function with 1 method)

julia> foo(1, 2)
You called foo with arguments: 1 2
and you got 6
6
1 Like
3

Thanks Robin.

This works for simple cases:

macro trace(global_flag, definition)
    definition = longdef(definition)
    if !@capture(definition, function f_(args__)
                     body__
                 end)
        error("Malformed function definition")
    end
    quote
        function $(esc(f))($(esc.(args)...))
            function inner()
                $(esc.(body)...)
            end
            if $(esc(global_flag))
                println("Trace enter ", $f, " ", join(($(esc.(args)...),), ' '))
            end
            result = inner()
            if $(esc(global_flag))
                println("Trace return ", result)
            end
            result
        end
    end
end
@trace (macro with 1 method)

trace_foo= true
true

@trace(trace_foo, foo(x) = x + 1)
foo (generic function with 1 method)

foo(2)
Trace enter foo 2
Trace return 3
3

but for a method with specializers or keyword arguments

@trace(trace_foo, foo(x::Int; y=0) = x + y)
ERROR: syntax: unexpected semicolon in tuple
Stacktrace:
 [1] top-level scope
   @ none:1

That’s a result of the way it’s producing the output.

for the invovation foo(2; y=3), I’d like the trace output to print that expression. I don’t see how to rewrite the formal call expression, definition.args[1] in the context of the trace macro above, to get that expression. The rewrite would need to occur at run time since it needs the run time values of the traced function’s parameters.

4

Something like this?

using MacroTools: @capture

function format_keywords(keyword_args)
    join(("$(pair.first) = $(pair.second)" for pair in keyword_args), ", ")
end

macro trace(expr)
    ok = @capture(expr, function f_(args__; kw__)
            body__
            end)
    ok || error("Could not parse function definition")
    quote
        function $(esc(f))($(esc.(args)...); user_keywords...)
            function inner($(esc.(args)...); $(esc.(kw)...))
                $(esc.(body)...)
            end
            
            println("You called ", $f, " with arguments: ", 
                join(($(esc.(args)...),), ", "), "; ",
                format_keywords(user_keywords))
            result = inner($(esc.(args)...); user_keywords...)
            println("and you got ", result)
            return result
        end
    end
end

Usage:

julia> @trace function foo(x, y; a = 10, b = 2)
           z = x + y + a + b
           return 2 * z
       end
foo (generic function with 1 method)

julia> foo(1, 2; a = 5)
You called foo with arguments: 1, 2; a = 5
and you got 20
20
5

Thanks Robin.

I’m trying to make that solution more flexible. It currently won’t work with functions that don’t take keyword arguments.

I see that you are creating a string to delay function argument substitution until runtime. I’ve been trying to find a way todo that for expressions, but no joy yet.

6

I have it working:

Sorry about the baroque coding. I just have a better understanding of using the Expr constructor that the :() syntax.

I think the insight that got meover the line is that :blush: can appear in the head of an Expr.

It currently uses println to output the trace info. I’d like to get it to use logging instead, but when I replace the printlnwith @infoI get an error.

If I don’t get past that after some amount of head banging, I’ll open another thread.

Thanks for your help.