Flame graphs#

It can be nice to visualize where time is spent when executing code.

We have added Scott Fritchie's fork of eflame to help trace and generate flame graphs.

Important: as far as I can tell, you can only have one trace going on at any given time. Be aware!

kz_tracers#

The kz_tracers module (in core/whistle_apps) starts the trace. Currently it just traces the supplied pid() with an optional time to trace (default 100s but this is way too long for most requests).

Tracing Crossbar requests#

You can enable a trace for a crossbar request by adding a header x-trace-request: true.

You will also need to enable tracing as a system config: sup whapps_config set_default crossbar allow_tracing true This has performance implications so I wouldn't leave this enabled on a production environment.

Now try your cURL request:

curl -v -X PUT \
    -H "content-type:application/json" \
    -H "x-trace-request:true" \
    -d '{"data":{"credentials":"{HASH}","account_name":"master"}}' \
    http://localhost:8000/v2/user_auth

In your Erlang VM (if you're running in interactive mode), you should see some logs:

started trace for <0.10699.2> in <0.10700.2>
Tracer <0.10667.2>
self() <0.10700.2>
Starting tracer results: {v_global_and_local_calls,
                             {ok,[{matched,
                                      'whistle_apps@localhost.localdomain',
                                      24456},
                                  {saved,1}]}}
trace for <0.10699.2> done
trace formatted to /tmp/eflame.trace.out
<0.10699.2> Hello, world, I'm <0.10713.2> and I'm running....
<0.10706.2>

Writing to /tmp/eflame.trace.out for 3 processes... finished!

Once its finished, you need to run a script to create the svg file:

kazoo/deps/eflame$ cat /tmp/eflame.trace.out | ./flamegraph.riak-color.pl > /tmp/eflame.svg

Now load that into your browser and click around!

You can also remove the SLEEP time:

kazoo/deps/eflame$ cat /tmp/eflame.trace.out | grep -v 'SLEEP ' | ./flamegraph.riak-color.pl > /tmp/eflame.svg

Issues#

Sometimes nothing gets traced and no svg can be generated. You might see this in your VM:

started trace for <0.10645.2> in <0.10646.2>
Tracer <0.4131.0>
self() <0.10646.2>
Starting tracer results: {v_global_and_local_calls,
                             {ok,[{matched,
                                      'whistle_apps@localhost.localdomain',
                                      24456},
                                  {saved,1}]}}
trace for <0.10645.2> done
trace formatted to /tmp/eflame.trace.out


Writing to /tmp/eflame.trace.out for 0 processes... finished!

I haven't bothered looking into this yet, as rerunning the request to do another trace usually gets some output. I think it depends on how fast the request is processed?

Edit this page here