Putting It Together—Tracing Method Calls

Let’s work through a larger example. We want to write a module called Tracer. If we use Tracer in another module, entry and exit tracing will be added to any subsequently defined function. For example, given the following:

use/tracer.ex
 defmodule​ Test ​do
 use​ Tracer
 def​ puts_sum_three(a,b,c), ​do​: IO.inspect(a+b+c)
 def​ add_list(list), ​do​: Enum.reduce(list, 0, &(&1+&2))
 end
 
 Test.puts_sum_three(1,2,3)
 Test.add_list([5,6,7,8])

we’d get this output:

 ==> call puts_sum_three(1, 2, 3)
 6
 <== returns 6
 ==> call add_list([5,6,7,8])
 <== returns 26

My approach to writing this kind of code is to start by exploring what we have to work with, and then to generalize. The goal is to metaprogram as little as possible.

It looks as if we have to override the def macro, which is defined in Kernel. So let’s do that and see what gets passed to def when we define a method.

use/tracer1.ex
 defmodule​ Tracer ​do
 defmacro​ ​def​(definition, ​do​: _content) ​do
  IO.inspect definition
 quote​ ​do​: {}
 end
 end
 
 defmodule​ Test ​do
 import​ Kernel, ​except:​ [​def​: 2]
 import​ Tracer, ​only:​ [​def​: 2]
 
 def​ puts_sum_three(a,b,c), ​do​: IO.inspect(a+b+c)
 def​ add_list(list), ​do​: Enum.reduce(list, 0, &(&1+&2))
 end
 
 Test.puts_sum_three(1,2,3)
 Test.add_list([5,6,7,8])

This outputs

 {:puts_sum_three, [line: 12],
  [{:a, [line: 12], nil}, {:b, [line: 12], nil}, {:c, [line: 12], nil}]}
 {:add_list, [line: 13], [{:list, [line: 13], nil}]}
 ** (UndefinedFunctionError) undefined function: Test.puts_sum_three/3

The definition part of each method is a three-element tuple. The first element is the name, the second is the line on which it is defined, and the third is a list of the parameters, where each parameter is itself a tuple.

We also get an error: puts_sum_three is undefined. That’s not surprising—we intercepted the def that defined it, and we didn’t create the function.

You may be wondering about the form of the macro definition: defmacro def(definition, do: _content)…. The do: in the parameters is not special syntax: it’s a pattern match on the block passed as the function body, which is a keyword list.

You may also be wondering if we have affected the built-in Kernel.def macro. The answer is no. We’ve created another macro, also called def, which is defined in the scope of the Tracer module. In our Test module we tell Elixir not to import the Kernel version of def but instead to import the version from Tracer. Shortly, we’ll make use of the fact that the original Kernel implementation is unaffected.

Let’s see if we can define a real function given this information. That turns out to be surprisingly easy. We already have the two arguments passed to def. All we have to do is pass them on.

use/tracer2.ex
 defmodule​ Tracer ​do
 defmacro​ ​def​(definition, ​do​: content) ​do
 quote​ ​do
  Kernel.​def​(​unquote​(definition)) ​do
 unquote​(content)
 end
 end
 end
 end
 
 defmodule​ Test ​do
 import​ Kernel, ​except:​ [​def​: 2]
 import​ Tracer, ​only:​ [​def​: 2]
 
 def​ puts_sum_three(a,b,c), ​do​: IO.inspect(a+b+c)
 def​ add_list(list), ​do​: Enum.reduce(list, 0, &(&1+&2))
 end
 
 Test.puts_sum_three(1,2,3)
 Test.add_list([5,6,7,8])

When we run this, we see 6, the output from puts_sum_three.

Now it’s time to add some tracing.

use/tracer3.ex
 defmodule​ Tracer ​do
 def​ dump_args(args) ​do
  args |> Enum.map(&inspect/1) |> Enum.join(​"​​, "​)
 end
 
 
 def​ dump_defn(name, args) ​do
 "​​#{​name​}​​(​​#{​dump_args(args)​}​​)"
 end
 
 defmacro​ ​def​(definition={name,_,args}, ​do​: content) ​do
 quote​ ​do
  Kernel.​def​(​unquote​(definition)) ​do
  IO.puts ​"​​==> call: ​​#{​Tracer.dump_defn(​unquote​(name), ​unquote​(args))​}​​"
  result = ​unquote​(content)
  IO.puts ​"​​<== result: ​​#{​result​}​​"
  result
 end
 end
 end
 end
 
 defmodule​ Test ​do
 import​ Kernel, ​except:​ [​def​: 2]
 import​ Tracer, ​only:​ [​def​: 2]
 
 def​ puts_sum_three(a,b,c), ​do​: IO.inspect(a+b+c)
 def​ add_list(list), ​do​: Enum.reduce(list, 0, &(&1+&2))
 end
 
 Test.puts_sum_three(1,2,3)
 Test.add_list([5,6,7,8])

Looking good:

 ==> call: puts_sum_three(1, 2, 3)
 6
 <== result: 6
 ==> call: add_list([5,6,7,8])
 <== result: 26

Let’s package our Tracer module so clients only have to add use Tracer to their own modules. We’ll implement the __using__ callback. The tricky part here is differentiating between the two modules: Tracer and the module that uses it.

use/tracer4.ex
 defmodule​ Tracer ​do
 
 def​ dump_args(args) ​do
  args |> Enum.map(&inspect/1) |> Enum.join(​"​​, "​)
 end
 
 def​ dump_defn(name, args) ​do
 "​​#{​name​}​​(​​#{​dump_args(args)​}​​)"
 end
 
 defmacro​ ​def​(definition={name,_,args}, ​do​: content) ​do
 quote​ ​do
  Kernel.​def​(​unquote​(definition)) ​do
  IO.puts ​"​​==> call: ​​#{​Tracer.dump_defn(​unquote​(name), ​unquote​(args))​}​​"
  result = ​unquote​(content)
  IO.puts ​"​​<== result: ​​#{​result​}​​"
  result
 end
 end
 end
 
 defmacro​ __using__(_opts) ​do
 quote​ ​do
 import​ Kernel, ​except:​ [​def​: 2]
 import​ ​unquote​(__MODULE__), ​only:​ [​def​: 2]
 end
 end
 end
 
 defmodule​ Test ​do
 use​ Tracer
 def​ puts_sum_three(a,b,c), ​do​: IO.inspect(a+b+c)
 def​ add_list(list), ​do​: Enum.reduce(list, 0, &(&1+&2))
 end
 
 Test.puts_sum_three(1,2,3)
 Test.add_list([5,6,7,8])