I've recently open-sourced a bare-bones, prototype tracing profiler for SBCL, that I developed as an internal tool at my last job. You can find the repository here. In its current form, it's a pile of hacks, but a surprisingly useful one. If you want to play with it, head over to the repository. I'm publishing it in hope that it'll be as useful to others as it was to me, and perhaps that someone will help me bring it to production quality - as a new parent, I have very limited time for it myself.
The repository README describes everything that's needed to know to use Tracer. The rest of this post contains a very quick intro to the idea of a tracing profiler, and some notes on the implementation of this particular one.
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.
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:
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
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
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).