# Method tracing in Julia?

**URL:** <https://discourse.julialang.org/t/method-tracing-in-julia/85387>\
**Category:** General Usage\
**Created:** [August 6, 2022, 8:07am UTC](https://discourse.julialang.org/t/method-tracing-in-julia/85387 "2022-08-06T08:07:17Z")\
**Posts on this page:** 6\
**Page:** 1

<div class="post-metadata">

**Author:** ![bertschi](https://sea2.discourse-cdn.com/julialang/user_avatar/discourse.julialang.org/bertschi/32/33462_2.png) [@bertschi](https://discourse.julialang.org/u/bertschi)\
**Post date:** [August 6, 2022, 8:07am UTC](https://discourse.julialang.org/t/method-tracing-in-julia/85387/1 "2022-08-06T08:07:18Z")

</div>

One of my favourite (and most missed) tools for exploring and debugging code is the trace facility often seen in Lisp. I.e., in Common Lisp, I can just _trace_ any function and get a view of its stack trace:

```nohighlight
CL-USER> (trace fib)
(FIB)

CL-USER> (fib 3)
  0: (FIB 3)
    1: (FIB 2)
      2: (FIB 1)
      2: FIB returned 1
      2: (FIB 0)
      2: FIB returned 0
    1: FIB returned 1
    1: (FIB 1)
    1: FIB returned 1
  0: FIB returned 2
2

```

where `fib` is just a naive recursive implementation of the Fibonacci numbers.

Using [Cassette.jl](https://github.com/JuliaLabs/Cassette.jl), I have hacked together a similar functionality in Julia:

```julia
using Cassette

Cassette.@context TraceCtx

function indent(i::Int, s::String)
    join(fill("", i), " ") * s
end

function Cassette.overdub(ctx::TraceCtx, args...)
    needprint = :all in ctx.metadata.funs || first(args) in ctx.metadata.funs
    if needprint
        if first(args) isa Core.Builtin
            meth = "Primitive $(first(args))"
        else
            meth = "Method $(which(first(args), Base.typesof(args[2:end]...)))"
        end
        println(indent(ctx.metadata.indent, "$meth called with $(args[2:end])"))
    end
    if Cassette.canrecurse(ctx, args...)
        newctx = Cassette.similarcontext(ctx, metadata = (funs = ctx.metadata.funs, indent = ctx.metadata.indent + 4))
        res = Cassette.recurse(newctx, args...)
    else
        res = Cassette.fallback(ctx, args...)
    end
    if needprint
        println(indent(ctx.metadata.indent, "returned $res"))
    end
    res
end

macro trace(expr, funs...)
    expresc = esc(expr)
    funsesc = esc.(funs)
    :(Cassette.overdub(TraceCtx(metadata = (funs = [$(funsesc...)], indent = 0)), () -> $expresc))
end

```

which can be used as follows:

```julia
julia> fib(n) = if n < 2 n else fib(n-1) + fib(n-2) end
fib (generic function with 1 method)

julia> @trace fib(3) fib
   Method fib(n) in Main at REPL[6]:1 called with (3,)
       Method fib(n) in Main at REPL[6]:1 called with (2,)
           Method fib(n) in Main at REPL[6]:1 called with (1,)
           returned 1
           Method fib(n) in Main at REPL[6]:1 called with (0,)
           returned 0
       returned 1
       Method fib(n) in Main at REPL[6]:1 called with (1,)
       returned 1
   returned 2
2

```

The nice thing about _trace_ is that it can be used interactively, shows all calls of selected functions no matter where and how deep they occur in the call stack and, in case of methods, also shows on which types exactly each call was dispatched.

Is this or a similar functionality already available in Julia, e.g., using some package? If not, did nobody ever wonder which methods – dispatched on which types exactly – get called across the call stack?

---

<div class="post-metadata">

**Author:** ![cormullion](https://sea2.discourse-cdn.com/julialang/user_avatar/discourse.julialang.org/cormullion/32/49131_2.png) [@cormullion](https://discourse.julialang.org/u/cormullion)\
**Post date:** [August 6, 2022, 8:24am UTC](https://discourse.julialang.org/t/method-tracing-in-julia/85387/2 "2022-08-06T08:24:22Z")

</div>

Perhaps you’d like [Ghost](https://github.com/dfdx/Ghost.jl), or is it now Umlaut?

---

<div class="post-metadata">

**Author:** ![ufechner7](https://sea2.discourse-cdn.com/julialang/user_avatar/discourse.julialang.org/ufechner7/32/51363_2.png) [@ufechner7](https://discourse.julialang.org/u/ufechner7)\
**Post date:** [August 6, 2022, 9:16am UTC](https://discourse.julialang.org/t/method-tracing-in-julia/85387/3 "2022-08-06T09:16:41Z")

</div>

Slightly different…

---

<div class="post-metadata">

**Author:** ![bertschi](https://sea2.discourse-cdn.com/julialang/user_avatar/discourse.julialang.org/bertschi/32/33462_2.png) [@bertschi](https://discourse.julialang.org/u/bertschi)\
**Post date:** [August 30, 2022, 9:31pm UTC](https://discourse.julialang.org/t/method-tracing-in-julia/85387/4 "2022-08-30T21:31:20Z")

</div>

Really does not seem to be available already …  
In any case, I have put together a small package from the above code snippet: [TraceMe.jl](https://github.com/bertschi/TraceMe.jl)

Hope some of you find it useful as well …

---

<div class="post-metadata">

**Author:** ![KingBoomie](https://sea2.discourse-cdn.com/julialang/user_avatar/discourse.julialang.org/kingboomie/32/29760_2.png) [@KingBoomie](https://discourse.julialang.org/u/KingBoomie)\
**Post date:** [September 9, 2024, 3:21pm UTC](https://discourse.julialang.org/t/method-tracing-in-julia/85387/5 "2024-09-09T15:21:00Z")

</div>

Hey @bertschi, thank you for your method tracing example!

I wanted to output a nice callgraph, so I modified it a little to output a TikzGraph graph instead:

```julia

using Cassette
using MetaGraphsNext
using TikzGraphs

Cassette.@context TraceCtx

function callstr(fun, args)
    fargs = join(args, ", ")
    "$fun($fargs)"
end

match(meth, fun::Function) = meth.name == nameof(fun)
match(meth, sym::Symbol) = sym == :all
match(meth, mod::Module) = meth.module == mod
function Cassette.overdub(ctx::TraceCtx, fun::Function, args...)
    meth = which(fun, Base.typesof(args...))
    needprint = any(match(meth, fun) for fun in ctx.metadata.funs)
	
	call_graph = ctx.metadata.call_graph
	cur_head_node = ctx.metadata.cur_head_node
	cur_v = nv(call_graph) + 1 

    if needprint
		call_graph[cur_v] = callstr(fun, args)
		call_graph[cur_head_node, cur_v] = nothing
    end
	
    if Cassette.canrecurse(ctx, fun, args...)
        newctx = Cassette.similarcontext(ctx, metadata = (
			funs = ctx.metadata.funs, 
			call_graph = call_graph, 
			cur_head_node = cur_v)
		)
        # Note: Work around potential Cassette bugs ...
        try
            res = Cassette.recurse(newctx, fun, args...)
        catch
            res = Cassette.fallback(ctx, fun, args...)
        end
    else
        res = Cassette.fallback(ctx, fun, args...)
    end
	
    if needprint
		call_graph[cur_v] = "$(callstr(fun, args)) = $res"
		call_graph[cur_head_node, cur_v] = nothing
    end
    res
end

macro trace(expr, funs...)
    expresc = esc(expr)
    funsesc = esc.(funs)

	call_graph = MetaGraph(
		DiGraph();
		label_type=Int,
		vertex_data_type=String
	)
	
	return quote
		local res = Cassette.overdub(TraceCtx(metadata = (funs = [$(funsesc...)], indent = 0, call_graph = $call_graph, cur_head_node = 1)), () -> $expresc)
		local node_labels = [string($call_graph[l]) for l in labels($call_graph)]
		local f = TikzGraphs.plot($call_graph.graph, node_labels)
		f
	end
end

```

and can be used the same way:

```julia
julia> fib(n) = if n < 2 n else fib(n-1) + fib(n-2) end
fib (generic function with 1 method)

julia> @trace fib(3) fib

```

![image](https://global.discourse-cdn.com/julialang/original/3X/d/f/df17378d7fb42559b428c8a49da052b64a0f325f.png)

This was my first delve into macros and Cassette.jl and your example was a nice starting point.

---

<div class="post-metadata">

**Author:** ![bertschi](https://sea2.discourse-cdn.com/julialang/user_avatar/discourse.julialang.org/bertschi/32/33462_2.png) [@bertschi](https://discourse.julialang.org/u/bertschi)\
**Post date:** [September 11, 2024, 7:52pm UTC](https://discourse.julialang.org/t/method-tracing-in-julia/85387/6 "2024-09-11T19:52:35Z")

</div>

That is pretty neat … would probably make sense to collect the information into a more general tree data structure, which could then be consumed by different backend, e.g., to produce my or your output.