Introducing Tracer - A Tracing Profiler for Common Lisp

In programming, tracing usually refers to recording or reporting on the execution of the program, with a particular attention to what functions were called in which order, what arguments were passed, and what they returned. Common Lisp has such a tracing facility built-in. You can use it to analyze recursive functions:

(defun flatten (list)
  (cond ((null list) nil)
        ((atom list) (list list))
        (t (append (flatten (car list))
                   (flatten (cdr list))))))

(trace flatten)
(flatten '(1 (2) 3))

;;; REPL output:

  0: (FLATTEN (1 (2) 3))
    1: (FLATTEN 1)
    1: FLATTEN returned (1)
    1: (FLATTEN ((2) 3))
      2: (FLATTEN (2))
        3: (FLATTEN 2)
        3: FLATTEN returned (2)
        3: (FLATTEN NIL)
        3: FLATTEN returned NIL
      2: FLATTEN returned (2)
      2: (FLATTEN (3))
        3: (FLATTEN 3)
        3: FLATTEN returned (3)
        3: (FLATTEN NIL)
        3: FLATTEN returned NIL
      2: FLATTEN returned (3)
    1: FLATTEN returned (2 3)
  0: FLATTEN returned (1 2 3)

Or function invocations:

(defun my-test (x)
  (and (oddp x)
       (> x 3)))

(defun my-key (x)
  (cadr x))

(trace my-test my-key)
(remove-if-not #'my-test '((c 3) (d 4) (e 5) (f 6)) :key #'my-key)

;;; REPL output:

  0: (MY-KEY (C 3))
  0: MY-KEY returned 3
  0: (MY-TEST 3)
  0: MY-TEST returned NIL
  0: (MY-KEY (D 4))
  0: MY-KEY returned 4
  0: (MY-TEST 4)
  0: MY-TEST returned NIL
  0: (MY-KEY (E 5))
  0: MY-KEY returned 5
  0: (MY-TEST 5)
  0: MY-TEST returned T
  0: (MY-KEY (F 6))
  0: MY-KEY returned 6
  0: (MY-TEST 6)
  0: MY-TEST returned NIL

Profiling refers to recording execution time and/or memory usage. Typically, this is done in one of two ways: either the code is instrumented directly with profiling instructions ("deterministic profiling"), or an external tool - known as a "sampling profiler" or "statistical profiler" is peeking at the program's call stack at high frequency. Both these methods usually provide a report as an aggregated statistics table, telling you how much time a particular function took on average and how many times it was seen called. Such data is immensely useful for finding the worst-performing pieces of an application, but it may be difficult to notice the code that slows down only in certain circumstances or when given certain types of input. More importantly, this table will not tell you what exactly was happening when your code suddenly slowed down.

Common Lisp doesn't have a profiler as a part of its standard, but some implementations provide them. For instance, SBCL ships with both deterministic and statistical profilers.

A tracing profiler combines the ideas of tracing and profiling. It's a deterministic profiler that doesn't aggregate its measurements, but instead stores every sample in a way that lets it reproduce the exact sequence of function calls along with information on how long each of that call took. Using it, the report can be presented as a flame graph like this:

This is a much nicer and more powerful presentation than one provided by regular profilers, and can give unique insights about why your code slows down occasionally, what is on the critical path of your application, or what larger call patterns look fishy.

You can learn more about tracing profilers and their usage in debugging hairy performance problems in this article by Dan Luu.

The screenshot above shows an example report of running the profiler I wrote - Tracer - as viewed through Google Chrome's little known Trace Viewer, available under a simple URL: about://tracing. After profiling designated pieces of code, Tracer produces a JSON file that can be directly loaded into the Trace Viewer and explored in the browser.

Trace Viewer was around for quite a while now; the original idea of using it for profiling my own code came from a 2012 Gamasutra article. I've been toying with it for about four years now, but it took some actual hard-to-diagnose performance problems at work to actually built the tool I needed.

The implementation itself is quick and dirty. In the introduction, I mentioned Tracer is a tool for SBCL, not for Common Lisp in general. That's because it coopts the implementation of the TRACE facility in SBCL in a very violent way: it briefly redefines a few internal functions to make them record profiling data instead of reporting the execution trace to *TRACE-OUTPUT*. Doing it this way makes Tracer completely non-portable, but it let me avoid reinventing the already-existing TRACE infrastructure, and this way the user doesn't have to modify any of their code - all one needs to do is to specify which functions should be profiled, and Tracer will just run a modified TRACE over them.

There's a nice consequence to that approach: profiling becomes quick and easy. At my last job, whenever myself or my teammates were trying to investigate a performance issue, we could just wrap a call the suspected function from the REPL in (with-tracing ...), and in a few moments we'd have a detailed report to explore. We could also wrap a call to sleep to just take a pulse of the application - Tracer records data across threads. With no need to modify or rebuild the actual code being profiled, exploring execution times became casual.

(A secondary benefit is that it allows for quick exploration of a large legacy codebase. If you're having trouble getting your head around who's calling who and why - as I often have in projects I'm new to - just set Tracer to trace every project package and explore the call graph visually!)

Tracer also supports optional recording of function arguments and return values (as nicely provided by the TRACE infrastructure). The interface to that is rather convoluted, but there's no good way to do it in a language that allows mutable state - you either store the values as you see them and risk them changing from under you, perhaps to an invalid state, or serialize them to strings immediately, incurring performance penalties and throwing off profiling). Nevertheless, this capability allows it to be used as a makeshift debugger. While Trace Viewer's UI isn't the most convenient for browsing argument lists, seeing them in context of a recorded call graph means you can explore the flow of data at a leisurely pace.

I'm glad the company I worked for allowed me to open-source Tracer. Even though at this point it's a bunch of non-portable spaghetti that was only tested on recent versions of SBCL, it already proved its worth by paying for itself the moment I used it on the work codebase. I believe it's a start of a useful tool, or at a very least a proof of concept. I'm hoping to eventually make it more robust and portable across implementations (even if it means hacking every TRACE implementation there is).