Using the Event Tracer tool set in Erlang

A common problem in concurrent systems is the following: events fire from all places all the time and you have no direct control over when and why events fire. Thus, to figure out problems one can often make use of a sequence diagram like this one (thanks Wikipedia):

The purpose of such a diagram is to show the interactions between different concurrent parties. In this case, Fred, Bob, Hank and Renee - in a restaurant. One can easily draw such diagrams on paper. But the problem with such a drawing is that it is disconnected from the machine. What the drawing shows may or may not be what the program actually does.

Wouldn't it be neat if you could make such diagrams by tracing what the code does and then build up the diagram in a programmatic way? Well, with Erlang, you can. I'll use some code I wrote as an example for how to do it.

Step 1: Build a tracer function
The first step is to construct a tracer function. Mine look like the following and resides in a module called "utp".

report_event(DetailLevel, FromTo, Label, Contents) ->
    %% N.B External call
    ?MODULE:report_event(DetailLevel, FromTo, FromTo, Label, Contents).

report_event(_DetailLevel, _From, _To, _Label, _Contents) ->
    hopefully_traced.

The basic idea is found in the latter of these two definitions. It defines a dummy-function taking 5 arguments which are thrown away promptly. The return value "hopefully_traced" is arbitrary, but it signifies what we want out of this function. The first variant, is used when it is the same party that does both things.

The arguments are as follows:

• DetailLevel: A number between 0 and 100. It signifies the level of detail for this event. We can use it to give major events low level and more detailed event at a finer grained scale higher levels. The event tracer can cut off events based on this value so we get the desired graininess.
• From: The party from which the event originates.
• To: The party to which the event is sent.
• Label: The notational label to put on the message.
• Contents: If you click on the event, we will show this term to the user. It can be used to pack up more detailed information to present, while avoiding cluttering up the diagram.

Step 2: Trace the events in the program
Whenever something important in the program happens, you add a call to "utp:report_event/5" or whatever the designation for your tracing function is. This will be default do nothing, but it allows us to hook that function later with Erlangs tracing facilities. As an example, here is the interaction from above:

trace_test() ->
    Events = [{fred, bob, order_food},
              {bob, hank, order_food},
              {bob, fred, serve_wine},
              {hank, bob, pickup},
              {bob, fred, serve_feed},
              {fred, renee, pay}],
    [utp:report_event(50, F, T, L, [])
     || {F,T,L} <- Events].

But note that anything can be reported really, by spreading the event reporting function out over your code base. Rather than run scores of debug statements, you can add a reporter at the point in the code. Also note I have condensed it a bit in the above example with a list comprehension because I don't care for the detail level and the contents.

Step 3: Introduce code to invoke the et application
Next, we need to invoke Erlangs et application in the right way. I have a module, called "utp_filter" which does it, even though it still doesn't contain any filter function. Here is the code of interest:

start(ExtraOptions) ->
    Options =
        [{event_order, event_ts},
         {scale, 2},
         {max_actors, 10},
         {detail_level, 90},
         {actors, [fred, bob, hank, renee]},
         {trace_pattern, {utp, max}},
         {trace_global, true},
         {title, "uTP tracer"} | ExtraOptions],
    et_viewer:start(Options).

What this code does is to initalize the et_viewer in a way such that it can be used with our example. The event order is event_ts which means we are timestamping events at when they fire and not when they are received. The actors define the order in which the actors appear. The trace_pattern is pretty important. It is what makes us hook to the "utp:report_event/5" call. You can give a lot of options to this or event produce such patterns yourself. But just name the module in which your trace function is placed will work.

Step 4: Test
If we invoke "utp_filter:start([])" which starts up the et viewer by executing the code in step 3, we can then invoke the trace test code from step 2 to obtain:

Which should reflect the example from Wikipedia, but now obtained by executing a program in Erlang. This idea has been used by me to capture and find bugs in TCP-stack variants, in particular uTP:

(Even if these diagrams are small, the basic idea should be in there - it is not about the diagrams, but about the steps to obtain the glory yourself :). For a TCP stack-like protocol it is very powerful: You have a tcpdump(1) output, an strace(1) output, as well as the internal protocol state in the same diagram. I found quite some bugs with these tools in my code, simply by inspecting the interaction of the programs.

And thats it. With the above code in your application, you can enable a graphical trace viewer on your code at any time. If you don't enable it, the overhead of the trace functions are negligible - unless you have a very hot critical path indeed. If you do enable it, you can see exactly what your code does in the given situation.