Wednesday, February 8, 2012

TRACEs of awesomeness

Debugging is hard, and I admit it freely: I am using print statements regularly to debug code that I'm writing, in particular when not writing Lisp code. With Lisp and its interactive development environment, though, my debugging activity often involves calling functions from the repl and tracing individual functions.

The standard TRACE facility that Common Lisp offers often replaces adding debug print statements for me. In order for tracing to help, the code needs to be structured so that a function is called at the place that is interesting in the particular debug situation. In many situations, one is not really interested in all invocations of a function, but only under some conditions. When debugging functions that are called often or that have large argument lists, simple traces can easily grow huge and analyzing trace logs can become a pain. Also, the trace output can slow down processing enough to make the simple approach fail.

Where TRACE's full power lives

The CLHS entry on TRACE suggests that there may be implementation dependent arguments, and in fact most implementations provide additional options that make the TRACE facility much more powerful. In this post, I'm going to show you a few examples of advanced TRACE options in three implementations to show what one may expect to be available. The examples and implementations chosen are pretty arbitrary and are not indicative of what the particular tracing facilities offer. Please look up the details in the respective documentation.

Breaking with CCL

Clozure CL's TRACE supports :BREAK-BEFORE to enter the debugger before a function is called:

Welcome to Clozure Common Lisp Version 1.7-r15160M  (DarwinX8664)!
? (defun foo ())
? (trace (foo :break-before t))
? (foo)
0> Calling (FOO) 
> Break: FOO trace entry: NIL
> While executing: (CCL::TRACED FOO), in process listener(1).
> Type :GO to continue, :POP to abort, :R for a list of available restarts.
> If continued: Return from BREAK.
> Type :? for other options.
1 > :go
<0 FOO returned NIL
Notice how the debugger is entered before FOO is called.

Statically selective tracing with Allegro CL

Sometimes, one only wants to trace a function when it is called from a certain other function. Allegro Common Lisp's tracer offers the :INSIDE option:

International Allegro CL Enterprise Edition
8.2 [64-bit Mac OS X (Intel)] (Dec 21, 2011 13:59)
Copyright (C) 1985-2010, Franz Inc., Oakland, CA, USA.  All Rights Reserved.
cl-user(1): (defun foo (arg) (format t "foo called, arg ~A~%" arg))
cl-user(2): (defun bar () (foo "from bar"))
cl-user(3): (defun qux () (foo "from qux"))
cl-user(4): (defun main () (bar) (qux))
cl-user(5): (trace (foo :inside qux))
cl-user(6): (main)
foo called, arg from bar
 0[2]: (foo "from qux")
foo called, arg from qux
 0[2]: returned nil
Note how the function FOO is called with no tracing when called from BAR, but with tracing from QUX.

Dynamically selective tracing with SBCL

Sometimes, one wants to trace a function based on some dynamic condition. SBCL's tracing facility offers this, as well as programmatic access to the argument list of the function being called:

This is SBCL, an implementation of ANSI Common Lisp.
* (defun foo (arg) (format t "foo called, arg ~A~%" arg))
* (defun bar () (foo 1) (foo 2))
* (trace foo :condition (= (sb-debug:arg 0) 2))
* (bar)
foo called, arg 1
  0: (FOO 2)
foo called, arg 2
  0: FOO returned NIL
Note how tracing is only enabled when FOO is called with a specific argument value.

Wrapping up

The purpose of this post was to show you some of the non-standard tracing options that Common Lisp implementations offer. As you can see, they are powerful debugging tools that can be used with no source code changes required. As these options are not standardized, make sure that you check out the documentation of your implementation. Happy debugging!



  1. Thanks for this post. I have been using (SB)CL for a couple of years now but didn't realize that you can give extra options to TRACE.

  2. FYI, here's a link to the LispWorks trace extensions:

  3. Printing time spent in the call, with LispWorks trace:

    (trace (myfunc
    :eval-before ((push (get-internal-real-time) *trace-times*))
    :after ((format nil "Real time: ~d"
    (- (get-internal-real-time)
    (pop *trace-times*))))))