Aspect-oriented: a motivating example

Gather round, and I shall tell you a fine tale. Once upon a time, there was a simple function in an API, a thin wrapper over more meaty code:

(defn do-a-thing [x stuff] (.doThatThing x stuff))

But a time came when we wanted to log every time it was called:

(defn do-a-thing
  [x stuff]
  (log/trace "calling function: app.api/do-a-thing")
  (.doThatThing x stuff))

Of course, we wanted to do the same with many functions in our codebase. This would lead to unnecessary code bloat, so we employed a standard and idiomatic solution that simultaneously:

• reduced the amount of bureaucratic code.
• ensured that we could switch out clojure.tools/logging for another solution in all places at any time.
• avoided bloating the call stack with unnecessary functional wrapping.

That is, we defined a new defn-like macro that would automatically generate the appropriate logging line. This was an improvement. We could replace the definition for do-a-thing and the many other logged functions with this simple line:

(def-logged-fn do-a-thing [x stuff] (.doThatThing x stuff))

Soon after, we wanted to know how long each call to do-a-thing would take:

(def do-a-thing-timer (metrics/timer "Timer for the function: app.api/do-a-thing"))

(metrics/register metrics/DEFAULT
                  ["app.api" "do-a-thing" "timer"]
                  do-a-thing-timer)

(def-logged-fn do-a-thing
  [x stuff]
  (let [context (.time timer)
        result (.doThatThing x stuff)]
    (.stop context)
    result)))

At first, all the functions we were logging were also functions we wanted to time, so we wrote a macro to generate all this code and let us go back to something simple, this time saving ourselves a few hundred lines of fragile copy-paste boilerplate:

(def-logged-and-timed-fn do-a-thing [x stuff] (.doThatThing x stuff))

But alas! Our needs still grew, and several things happened at once. We incorporated tracing into our codebase, and we no longer wished for all our logged functions to be timed, or for all our timed functions to be traced, or all our traced functions to be logged -- we wanted any combination of the three. The optimizations we'd made no longer applied, so our little one-line wrapper was up to twenty-seven lines. Even after applying common Clojure-idiomatic mitigation techniques, it was not ideal:

(def ^:private do-a-thing-timer
  (metrics/register-a-timer! metrics/DEFAULT :function ["api.api" "do-a-thing"]))
(defn do-a-thing
  [x stuff]
  (log/trace "calling function: app.api/do-a-thing")
  (metrics/with-timer do-a-thing-timer
    (tracing/with-tracing "app.api/do-a-thing:[x stuff]"
      (.doThatThing x stuff))))))

Multiply this effect by the number of functions we apply telemetry to across our entire service. It is tedious, and contains a good deal of copy-paste code, fragile under inevitable future changes (for instance, swapping out a logging library or modifying the metrics implementation). Moreover, all that boilerplate is very distacting if you care about the business logic and nothing else. What it seemed we really needed was a full suite of def-*-fns:

• def-logged-fn
• def-traced-fn
• def-timed-fn
• def-logged-traced-fn
• def-logged-timed-fn
• def-traced-timed-fn
• def-logged-traced-timed-fn

That, of course, is ridiculous. Besides, with just one additional fourth axis, we'd need 15 of these. For n, 2ⁿ-1.

The key to solving our problem once and for all was to recognize that these were all completely independent aspects of a function definition. None of the manual transformations depended on any of the others. Thus was born morphe. Our one-liner could once again be a one-liner:

(m/defn ^{::m/aspects [timed logged traced]} do-a-thing [x stuff] (.doThatThing x stuff))

And in case you are skeptical as to how this solves any problem in the first place, remember that the best predictor of bug count in a code base is the size of the code base. This library has a number of potential applications, but the easiest all involve removing boilerplate.

I no longer have exact numbers, but at one point I estimated in a Clojure project a few tens of thousands of lines large that the application of cross-cutting aspects to ~2% of my project's functions resulted in a ~25% LOC reduction, not to mention greater programmer consistency in adhering to those cross-cutting concerns.