dbg module Elixir

using Erlang dbg module in Elixir for tracing

Example 0. Trace all calls and all messages in the module

The module AnApp.ex accepts and makes calls and receives and sends messages:

defmodule AnApp do
    def start do
        spawn(&loop/0)
    end

    def loop do
        receive do
            {From, x} -> send(From, __MODULE__.f1(x))
            _ -> :ok
        end
    __MODULE__.loop()
    end

    def f1(x) do
        f2(x)
    end

    defp f2(x) do
        sin(x)
    end

    defp sin(x) do
        :math.sin(x)
    end
end

Let us ompile it first with elixirc AnApp.ex.
Now we can trace it.
In Elixir shell:

Erlang/OTP 24 [erts-12.0] [source] [64-bit] [smp:8:8] [ds:8:8:10] [async-threads:1] [jit]

Interactive Elixir (1.12.2) - press Ctrl+C to exit (type h() ENTER for help)
iex(1)> cd "d:/src/my_working_folder"
d:/src/my_working_folder
iex(3)> require AnApp
AnApp
iex(5)> s = AnApp.start
#PID<0.111.0>

Now prep the :dbg facility:

iex(11)> :dbg.tracer()
{:ok, #PID<0.119.0>}
iex(13)> :dbg.tpl(AnApp,:'_',:x) # trace all functions of an_app, with return_value 
{:ok, [{:matched, :nonode@nohost, 10}, {:saved, :x}]}
iex(15)> :dbg.p(:all, :c)        # trace all processes, calls with the local trace pattern above
{:ok, [{:matched, :nonode@nohost, 60}]}
iex(17)> :dbg.p(s)               # trace all messages sent and received by the process s
{:ok, [{:matched, :nonode@nohost, 1}]}

We are all set.
Let us give it a shot:

iex(19)> AnApp.f1 1.57
(<0.105.0>) call 'Elixir.AnApp':'__info__'(macros)
(<0.105.0>) returned from 'Elixir.AnApp':'__info__'/1 -> []
(<0.105.0>) call 'Elixir.AnApp':'__info__'(deprecated)
(<0.105.0>) returned from 'Elixir.AnApp':'__info__'/1 -> []
(<0.105.0>) call 'Elixir.AnApp':f1(1.57)
(<0.105.0>) call 'Elixir.AnApp':f2(1.57)
(<0.105.0>) call 'Elixir.AnApp':sin(1.57)
(<0.105.0>) returned from 'Elixir.AnApp':sin/1 -> 0.9999996829318346
(<0.105.0>) returned from 'Elixir.AnApp':f2/1 -> 0.9999996829318346
(<0.105.0>) returned from 'Elixir.AnApp':f1/1 -> 0.9999996829318346
0.9999996829318346

... it worked!
how about messages?

iex(21)> send(s , {self, 1.57})
(<0.111.0>) << {<0.116.0>,1.57}
0.9999996829318346
(<0.111.0>) call 'Elixir.AnApp':f1(1.57)
{#PID<0.116.0>, 1.57}
(<0.111.0>) call 'Elixir.AnApp':f2(1.57)
(<0.111.0>) call 'Elixir.AnApp':sin(1.57)
(<0.111.0>) returned from 'Elixir.AnApp':sin/1 -> 0.9999996829318346
(<0.111.0>) returned from 'Elixir.AnApp':f2/1 -> 0.9999996829318346
(<0.111.0>) returned from 'Elixir.AnApp':f1/1 -> 0.9999996829318346
(<0.111.0>) <0.105.0> ! 0.9999996829318346
iex(23)> (<0.111.0>) call 'Elixir.AnApp':loop()

iex(24)> flush
0.9999996829318346
:ok

nice!

---

the original study:

Prepare the Echo server to study

   defmodule Echo do     
      def start do
         spawn(&loop/0)
      end

      defp loop do
          receive do
             m -> IO.inspect(m)
                  loop()
          end
      end
   end

   echo = Echo.start()
#PID<0.218.0>

Example 1. Trace all actions in a certain process

     :dbg.tracer()      # :dbg module has its own tracer
     :dbg.p(echo, :all)
     send(echo, :hi)    # a slew of tracing data:
:hi
:hi
(<0.218.0>) in {'Elixir.Echo',loop,0} (Timestamp: {1633,194976,262121})
iex(46)> (<0.218.0>) << hi (Timestamp: {1633,194976,262122})
(<0.218.0>) gc_minor_start [{wordsize,11}, ... skipped
(<0.218.0>) gc_minor_end ... skipped ...
(<0.218.0>) <0.65.0> ! {io_request,<0.218.0>,
                                   #Ref<0.3176856020.1409548295.192147>,
                                   {put_chars,unicode,<<":hi\n">>}} (Timestamp: {1633,
                                                                                 194976,
                                                                                 262127})
(<0.218.0>) out {io,execute_request,2} (Timestamp: {1633,194976,262128})
(<0.218.0>) in {io,execute_request,2} (Timestamp: {1633,194976,262129})
(<0.218.0>) << {io_reply,#Ref<0.3176856020.1409548295.192147>,ok} (Timestamp: {1633,
                                                                               194976,
                                                                               262130})
(<0.218.0>) out {'Elixir.Echo',loop,0} (Timestamp: {1633,194976,262131})

      :dbg.stop_clear() # let us stop tracing
:ok
iex(48)> send(echo,:hi) # no more tracing:
:hi
:hi

Example 2. Trace function call math:sin for all processes

   :dbg.tracer()
   :dbg.p(:all,:c)
   :dbg.tpl(:math, :sin, 1, :x)
   :math.sin(1)
(<0.105.0>) call math:sin(1)
(<0.105.0>) returned from math:sin/1 -> 0.8414709848078965
0.8414709848078965
   :dbg.stop_clear()

Example 3. Trace function call math:sin in all processes with the argument 3.14 only

    [{x,z,[y]}] = :dbg.fun2ms(fn([x]) when x == 3.14 -> :return_trace end)

    ms = [{x,z,[{y}]}]  # now we have a match spec
[{[:"$1"], [{:==, :"$1", 3.14}], [{:return_trace}]}]

    :dbg.tracer()
    :dbg.p(:all,:c)
    :dbg.tpl(:math, :sin, 1, ms)

    :math.sin(1) # no trace as expected:
0.8414709848078965

    :math.sin(3.14) # now the call and the return values as expected:
(<0.105.0>) call math:sin(3.14)
(<0.105.0>) returned from math:sin/1 -> 0.0015926529164868282
0.0015926529164868282