There was a time when programmers spent a great deal of time and energy on making their programs run faster. With faster machines, we don’t have to worry so much about performance these days.

But once in a while we may run into a problem where performance is critical or the program is running noticeably slow. People often resort to sophisticated profilers and do some test runs to identify the “hot-spots” in the program.

Sometimes the performance problems surface only after the program has run for a considerable duration in production. A usual way to solve such problems has the following steps:

  1. You identify some functions as suspect and sprinkle them with log statements to reveal the bottlenecks.
  2. After the problem is identified and fixed, you remove or comment out the log statements.
  3. Make a new build and deploy.

But this time a new bottleneck emerges from another call path!

This is when you wish you had a more dynamic profiler that could be enabled only for certain functions, and once the performance numbers are available, can be turned-off via simple configuration.

This post will show the design of such a simple and configurable profiler for Clojure.

The profiler is implemented as a macro called trace. It makes use of the intern function.

The macro arguments are two symbols identifying the namespace and function to be instrumented. The macro will take a “backup” of the function, and then intern a new version of it instrumented with code for capturing and reporting performance metrics.

The implementation of the trace macro is shown below:

(def backups (atom {}))

(defn make-key [nsname fnname]
  (symbol (str (second nsname) "/" (second fnname))))

(defmacro trace [nsname fnname]
  (let [k (make-key nsname fnname)]
    `(let [orig-fn# ~k
           instrumented-fn# (fn [& args#]
                              (let [start-nanos# (System/nanoTime)
                                    result# (apply orig-fn# args#)
                                    end-nanos# (System/nanoTime)
                                    log-call# (concat (list '~k) args#)]
                                (print "TRACE:" (doall log-call#))
                                (print " =>" (str (- end-nanos# start-nanos#) "ns"))
                                (println " =>" result#)
                                result#))]
       (swap! backups assoc '~k orig-fn#)
       (intern ~nsname ~fnname instrumented-fn#))))

Once metrics from a function is captured, you may want to remove its instrumentation. This can be achieved by simply re-configuring and restarting the program.

If you want to avoid a restart, you may dynamically restore the original function, by interning the function object from the “backup”. The untrace macro defined below enables this feature.

(defmacro untrace [nsname fnname]
  (let [k (make-key nsname fnname)]
    `(let [k# '~k]
       (intern ~nsname ~fnname (get @backups k#))
       (swap! backups dissoc k#))))

The following program demonstrates how to use the trace/untrace pair for capturing performance metrics of a function:

(ns trace.test)

(defn f [x y]
  (* x y))

;; ...
(println (f 10000000 200))
(trace 'trace.test 'f)
(println (f 10000000 200))
(untrace 'trace.test 'f)
(println (f 10000000 200))

A sample run of this program generated the following output on my laptop:

2000000000
TRACE: (trace.test/f 10000000 200) => 14498ns => 2000000000
2000000000
2000000000

The objective of this post was to demonstrate an idea that enables your applications to be instrumented on demand.

You may want to adapt and extend the code to fit your needs, like updating the trace macro to produce output suitable for the particular logging and reporting tools that you use.


Note that name and e-mail are required for posting comments