Skip to content

Latest commit

 

History

History
193 lines (140 loc) · 6.15 KB

debugging-with-tracing-in-elixir-with-recon_trace.livemd

File metadata and controls

193 lines (140 loc) · 6.15 KB

Debugging with Tracing in Elixir with recon_trace

Introduction

In my blog post, Debugging with Tracing in Elixir, I mentioned about using recon_trace from recon to trace your function calls in your live system.

After using recon_trace a few times and always needing to going back to the documentation to figure out how to use it correctly, I decided to write this to document the common usage I came across.

This is what you can expect from this notebook, hopefully it helps!

  • Installing recon
  • Tracing function with return trace/value
  • Tracing more specific function calls
  • Writing match spec]

Installing recon

First of all, let's install :recon as part of our dependencies into our Livebook. With Elixir 1.12, it is as simple as using Mix.install.

Mix.install([
  :recon
])

Alternatively, you can add the dependencies of recon into your mix.exs as follow:

defp deps do
  [
    # ... other depedencies,
    {:recon, "~> 2.5"}
  ]
end

Tracing function with return trace/value

To trace a function with recon, it is as simple as calling :recon_trace.calls({module, function, match_spec}, max_trace, opts \\ []):

{max_trace, _} = IO.gets("Max Trace") |> Integer.parse()
:recon_trace.calls({Enum, :map, :return_trace}, max_trace)

list1 = [1, 2, 3, 4]
Enum.map(list1, fn x -> x + 2 end)
Enum.map(list1, fn x -> x - 2 end)
Enum.map(list1, fn x -> x * 2 end)
Enum.map(list1, fn x -> x / 2 end)

The example above are tracing Enum.map function and telling recon_trace to receive traces of at most 4. If you run the code above, you'll see the traces of the first 2 function calls.

Why not 4 function calls? Since our max trace is 4.

This is because, when we are using :return_trace, each function call will have 2 traces:

  • one for the function call
  • one for the result trace

You'll also see Recon tracer rate limit tripped., which is recon_trace telling you that it is rate limited, and you'll not receive any new traces regarding the function call.

Play around with the Max Trace input to feel the difference!

Tracing more specific function calls

Same with using dbg, you can also use recon_trace to trace more specific function call by altering your match spec for :recon_trace.calls.

Let's say we want to trace function call of Enum.map with matching the arguments [1,2,3] specifically. We can achieve that by using this match spec:

[
  {
    [[1, 2, 3], :_],
    [],
    [{:return_trace}]
  }
]

Looks complicated right? Don't worry, let me break it down for you.

A match spec is a list [] of 3 elements tuple {_, _, _}, with only one item in the list [{_, _, _}].

Here's what the 3 elements of the tuple refers to:

  • 1st: indicate the function arguments that we want to match. Here, with Enum.map/2:
    • first parameter is the enumerable pass into Enum.map, which is [1, 2, 3].
    • second parameter is the anonymous function we pass into Enum.map.
  • 2nd: indicate the guards of the function, which is not applicable here. We will see it in action later below.
  • 3rd: indicate the actions of the match spec, which is the return_trace in our case.

Let's see this in action.

match_spec = [
  {
    [[1, 2, 3], :_],
    [],
    [{:return_trace}]
  }
]

:recon_trace.calls({Enum, :map, match_spec}, 4)
Enum.map([1, 2, 3], fn x -> x + 2 end)
Enum.map([1, 2, 3, 4], fn x -> x + 2 end)

Here we are telling recon_trace to trace Enum.map function call where the first argument is [1, 2, 3]. You'll notice that recon_trace only show the traces for the first function call and not the second.

Writing Match Spec

Writing the match spec seems complicated right? No worry, we can utilize :dbg.fun2ms to help us out.

match_spec = :dbg.fun2ms(fn [a, _] when length(a) > 4 -> :return_trace end)

match_spec =
  Enum.map(match_spec, fn {args, guards, [:return_trace]} ->
    {args, guards, [{:return_trace}]}
  end)

Here we are writing the match spec for tracing Enum.map where the first arguments length is larger than 4.

Notice that we need to do some additional transformation because as mentioned in my previous post, the match spec returned by dbg is not entirely correct. Hence, we have some additional transformation there.

Now, our second element is not an empty list anymore as shown in the previous example. I'm not going into the details on how to read the generated match spec, if you want to know more about it consider reading:

Let's see that in action.

:recon_trace.calls({Enum, :map, match_spec}, 4)
Enum.map([1, 2, 3, 4], fn x -> x + 2 end)
Enum.map([1, 2, 3, 4, 5], fn x -> x + 2 end)
Enum.map([1, 2, 3, 4, 5, 6, 7, 8], fn x -> x + 2 end)

You'll see that there is no tracing for first function call, as it only have 4 elements and does not fulfil our match spec.

Wrap Up

Tracing is an extremely useful debugging tool to add to your current toolkit. This is especially true when you need to debug live production system.

Personally, I have done that a few times in both of our staging and production environment. I can say that the experience is pleasant (once you figure out match spec and use it correctly...).

Last but not least, I highly recommend these resources below if you are interested into this topic particularly:

This Livebook content is also available as a blog post on my website.