Tracing, event_trace

[Luke Gorrie]

Hideyho,

I'm building up to learning about all the fancy tracing features of
recent OTP versions (amazing looking, but hard to approach!), but
meanwhile I wanted to share a small tracing framework that we have
been getting some value out of recently. It is basically one level of
sophistication above ?debug("Foo").

The program is at http://www.bluetail.com/~luke/misc/event_trace-0.1.tar.gz

README follows:

event_trace 0.1 -- A simple event tracing framework
============================================================

The intent of this module is to do printf-style debugging without
having to keep adding and removing io:format's or recompiling with
-Ddebug flags. The strategy is using the usual style of compile-time
debugging macros, but with the option to filter events by category at
runtime. This way you can leave the debug printouts in your code, and
compile-time enable them all while hacking, but use filters so that
you only see the details that you are interested in for a particular
debug run.

The central macro is ?event(Type, Fmt, Args) - Type is the
category. When compiled with -Devent_trace, this macro sends an
io:format-style debugging message to an event_trace server process,
which will either print or discard it depending on how the category
and filters. There are also ?event_val and ?event_time variants for
showing return values or running time.

The event_trace module allows events to be globally enabled or
disabled by category. Enabled events are printed with io:format/2, and
tagged with the category and the module/line where they came from.

The file et_example.erl shows the principle. It is a toy program that
connects to an SMTP server, says "HELO", and disconnects. It traces
two categories of events: 'net' (results of gen_tcp calls) and 'main'
(higher level stuff). It exports a few functions that run with
different debug levels, which run like this:

High-level events..

  (erlang@REDACTED)12> et_example:main("localhost").
  [main et_example:16] Starting using host "localhost"
  [main et_example:21] Handshake ok!

Networking events..

  (erlang@REDACTED)13> et_example:net("localhost").
  [net et_example:34] connect() to "localhost" => {ok,#Port<0.57>}
  [net et_example:40] send() of HELO => ok
  [net et_example:43] recv() of reply => {ok,"220 cockatoo ESMTP Exim 3.35 #1 Fri, 22 Nov 2002 18:02:00 +0100\r\n"}

All events..

  (erlang@REDACTED)14> et_example:all("localhost").
  [main et_example:16] Starting using host "localhost"
  [net et_example:34] connect() to "localhost" => {ok,#Port<0.58>}
  [net et_example:40] send() of HELO => ok
  [net et_example:43] recv() of reply => {ok,"220 cockatoo ESMTP Exim 3.35 #1 Fri, 22 Nov 2002 18:02:12 +0100\r\n"}
  ok
  [main et_example:21] Handshake ok!

There is also a Distel-based Emacs client, event-trace.el. This
receives all events from the event_trace server (enabled or not), and
can then (re)filter them locally.

The overhead of tracing should be as follows:

Disabled at compile time:
  no overhead

Disabled at run time:
  just message send of fmt+args to event_trace server (no actual
  string formatting)

Enabled at runtime:
  Send + io:format

Emacs connected:
  All events are always formatted on the erlang node and then
  forwarded to Emacs. (Actually this also happens after the emacs
  process is killed, which is a performance bug..)

-- luke@REDACTED