Clojure observability and debugging tools

There are a range of observability tools we can use in conjunction with the REPL to explore and debug our code. My use-case is being able to inspect code during development, as I play with the code, to see what's happening. The tools I'm going to show help us inspect what forms (expressions) are doing, how values change and trace functions. These tools fill a gap before we get to full debuggers.

The step before these tools is that many editors have in-line evaluation (e.g Visual Studio Code/Calva, Vim iced) where you can see the evaluated value next to the individual form. The next step beyond in-line evaluation is to be able to observe the behaviour of a set of steps in our code and functions.

Spyscope is the most well-known library in this space and it's very useful. It doesn't work properly with Clojure 1.10 as the version available on Clojars is out of date. The alternative tools I'm using are:

There are lots of other debugging, tracing and logging libraries in the Clojure ecosystem. The main ones I found referenced were:

For each tool I've looked at I'll show a standard set of examples to give a flavour of what they'll show across different situations.

Hashp

Hashp and Spyscope are similar to each other. They use the REPL's data reader to rewrite the form (expression) in a way that it can show debug information. Hashp's compatible with both Clojure and ClojureScript.

Where hashp shines is that it's easy to use for observing the values across a few expressions. Due to the way it works you don't need to rewrite the expressions (forms) - you can just put #p in your code to quickly see what's happening.

Add it to ~/.lein/profiles.clj or your specific project's project.clj. It doesn't add any appreciable time to the REPL's start-up so I have it set to load all the time:

{:user
    {:dependencies [[hashp "0.1.1"]]
     :injections [(require 'hashp.core)]}}

The :injections line is loading the library into the REPL's namespace, you can also do this in a user.clj as we showed in a previous post.

It provides a #p that you can put in front of any form that you want to print:

; Example 1: printing the value of a form, we want the value of the addition
user=> (take 20 (repeat #p (+ 1 2 3)))
#p[user/eval9223:1] (+ 1 2 3) => 6
(6 6 6 6 6 6 6 6 6 6 6 6 6 6 6 6 6 6 6 6)

As you can see it's nice and simple, we simply place a #p in front of the form we want to print. Hashp shows us the form that's being evaluated clearly (in this case + 1 2 3) and the output. Lets look at a more complex example:

; Example 2: we want the value of each step
; (inc (* 2 (+ 3 (* 4 5))))

user=> (inc #p (* 2 #p (+ 3 #p (* 4 5))))
#p[user/eval9305:1] (* 4 5) => 20
#p[user/eval9305:1] (+ 3 (* 4 5)) => 23
#p[user/eval9305:1] (* 2 (+ 3 (* 4 5))) => 46
47

In the second example we want to understand each step so we've put #p's in front of each form. Notice that we didn't have to rewrite the code in any way, we're just adding #p and it's handling everything else. I find this layout really clear and it helps me understand what's happening immensely.

As with any simple tool there are limitations, the first one is that it doesn't work with the threaded macros.

; Example 3: we want the value after inc
; (-> 1 (inc) (* 2))

user=> (-> 1 (inc) #p (* 2))
clojure.lang.ExceptionInfo: Call to clojure.core/let did not conform to spec.
clojure.lang.Compiler$CompilerException: Syntax error macroexpanding clojure.core/let at (/tmp/form-init7373119383376874288.clj:1:1).


; Example 4: we want the output of the filter odd
(->> (range 10)
 (filter odd?)
 #p
 (map inc))

#p[user/eval9068:1] (map inc) => #<Fn@29bf90fc clojure.core/map[fn]>
(1 3 5 7 9)

Debux provides a better solution for observing these sorts of situation.

You can use Hashp to go through each step in a function adding #p's for each step you want to see. This is actually fine for small cases, a bit lower down we'll look at a Debux dbgn function that makes this easier by using a single debug function.

; Example 5: we want to see each step in a function
(defn mean [xs]
    (/ (double #p (reduce + xs)) #p (count xs)))

user=> (mean [1 4 5 2])
#p[user/mean:2] (reduce + xs) => 12
#p[user/mean:2] (count xs) => 4
3.0

The final constraint is that you can't use it to return Var values (or function return values) in the code. We'll cover this later with Debux.

The summary is that with Hashp you can easily adding a couple of #p's to a function to see what's happening. Quick and easy. It's the first step to seeing inside the black box. More powerful tools give insight, but you'll often have to start messing with the code to get the output.

Debux

Debux is an advanced debugging and observability tool, it carries on where Hashp ends. It's compatible with Clojure and ClojureScript. I'm only showing the highlights, check out the extensive documentation for more sophisticated examples. Debux provides specific tools to look at individual forms, but also to look at all the steps in a function.

To use it in development add the following to development dependencies in your project.clj:

:dev {
       :dependencies [[philoskim/debux "0.6.5"]]}

In env/dev/user.clj add the following:

[debux.core :refer :all]

If you want to observe a single value you use the dbg macro like so:

;; simple debug of a single form
user=> (* 2 (dbg (+ 10 20)))

{:ns user, :line 1}
dbg: (+ 10 20) =>
|   30
60

;; Example 1: printing the value of a form, we want the value of the addition
;; this is the same example shown above for Hashp
user=> (take 20 (repeat (dbg (+ 1 2 3))))

{:ns user, :line 1}
dbg: (+ 1 2 3) =>
|   6
(6 6 6 6 6 6 6 6 6 6 6 6 6 6 6 6 6 6 6 6)

As you can see we add a call to dbg and it shows us the output of that particular form. This is pretty similar to hashp though we did have to add some brackets. However, unlike hashp, it can be used to debug the threaded macro:

; Example 3: we want the value after inc
user=> (-> 1 (inc) dbg (* 2))

{:ns user}
dbg: (inc 1) =>
|   2
4

;; the other option is to dbg the whole thing and get all steps
user=> (dbg (-> 1 (inc) (* 2)))

dbg: (-> 1 (inc) (* 2)) =>
| 1 =>
|   1
| (inc) =>
|   2
| (* 2) =>
|   4
4

; Example 4: we want thread last macro output
user=> (->> (range 10)
 (filter odd?)
 dbg
 (map inc))

{:ns user}
dbg: (filter odd? (range 10)) =>
|   (1 3 5 7 9)
(2 4 6 8 10)

There's also a couple of options that we can provide that make both macros much more sophisticated. The first is that you can add a marker to the debug output:

(* 2 (dbg (+ 10 20) "adding"))

 {:ns user, :line 1}
 dbg: (+ 10 20)   <adding> =>
 |   30
 60

The :if option lets you decide whether you should print debug:

(doseq [i (range 10)]
    (dbg i :if (even? i)))

The print option lets you print something other than the format provided to you:

(+ 10 (dbg (* 20 30) :print #(type %)))

{:ns user, :line 1}
dbg: (* 20 30) =>
|   java.lang.Long
610

Debux dbgn

Debux also has a dbgn macro that shows you the output of a set of steps (multiple forms). It's perfect for wrapping a function to see what's happening:

;; debug each step of a function
(dbgn (defn func1 [guess]
        (let [rnd (rand-int 10)]
            (cond (= rnd guess) (println "You got it right")
                    :else (println "Sorry you are wrong!")
                   ))))

;; run the function
user=> (func1 5)

| (rand-int 10) =>
|   7
| rnd =>
|   7
| guess =>
|   5
| (= rnd guess) =>
|   false
Sorry you are wrong!
| (println "Sorry you are wrong!") =>
|   nil
| (cond (= rnd guess) (println "You got it right") :else (println "Sorry ... =>
|   nil
| (let [rnd (rand-int 10)] (debux.common.util/insert-blank-line) (cond ( ... =>
|   nil
nil

Imagine that we'd created this function previously but weren't quite sure what it's doing. It's easy to wrap it in dbgn and then it will show us the individual values and steps.

We can use dbgn anywhere we want to look at sequence of steps:

;; Example 2: we want the value of each step
(dbgn (inc (* 2 (+ 3 (* 4 5)))))

{:ns user, :line 1}
dbgn: (inc (* 2 (+ 3 (* 4 5)))) =>
| (* 4 5) =>
|   20
| (+ 3 (* 4 5)) =>
|   23
| (* 2 (+ 3 (* 4 5))) =>
|   46
| (inc (* 2 (+ 3 (* 4 5)))) =>
|   47
47

It's very easy to observe a function as we only need to wrap it. It then gives us the local variables and each form of the function.

Finally, both macros will return values passed to them - we can use this to get particular information like the value of a local Var:

;; Example 6: function return values - we want to see local values
(defn stats
    [fname [height weight] ]
        (let [i 10]
        (println fname "is" height)
        (dbg [fname height weight i])))

user=> (stats "Bob" [178 68])
Bob is 178

{:ns user, :line 5}
dbg: [fname height weight i] =>
|   ["Bob" 178 68 10]
["Bob" 178 68 10]

In this case we've told dbg we specifically want to know the value of i, so it's returned to us. We've had to tell Debux which Vars we want, lets look at Postmortem which provides a way to automate this.

Postmortem

Postmortem is a debugging tool focused on postmortem analysis. This tool is most useful when you're running a chain of functions and want to record elements across that chain of execution. I find the dump function for getting all local variables in a function really useful.

Add to ~/.lein/profiles.clj or to your project.clj:

[postmortem "0.4.0"]

Then add to env/dev/user.clj:

[postmortem.core :as pm]
[postmortem.instrument :as pi]

The main functions are:

  • (spy> expression :key)
    The spy> function stores the value of the expression as a log entry under the key. This is the thread-first version so takes the data first.
  • (spy>> :key (expression))
    The spy>> stores the value of the expression as a log entry under the key. This is the thread-last version so takes the data last.
  • (dump :key)
    Dump stores a local environment map to the log entry of :key. Very useful for quickly seeing how a function works.
  • (log-for :key)
    Returns all the logged data for the key.
  • (pm/reset-key! :key)
    We can reset a key by calling it.

Lets start by showing how to add spy> or spy>>:

; add a spy>> to the function
(defn mean [xs]
    (pm/spy>> :double (/ (double (reduce + xs)) (count xs))))

user=>(mean [1 4 5 2])
3.0

user=> (pm/log-for :double)
[3.0]

We've defined a function mean and put a spy>> in with a specific key of :double. When the function runs no special output is shown - unlike the other libraries we've looked at. Instead we access the specific log for that spy. In the last step we examine what was logged using the log-for function. Notice the way we use the key (:double) that we originally used for the spy>>.

We can log to the same key multiple times and it will record the details in the log for each call:

; reset first - explained lower down
(pm/reset-key! :double)

; if you call the function multiple times it records the spy each time
user=> (mean [1 4 5 2])
3.0

user=> (mean [1 7 5 4])
4.25
user=> (pm/log-for :double)
[3.0 4.25]

It's important to know that you can only access the log for a key using pm/log-for once: as soon as you do this the log is completed and any subsequent runs of the function won't change the data:

; reset first - explained lower down
(pm/reset-key! :double)

user=> (mean [1 4 5 2])
user=> (mean [1 7 5 4])
user=> (pm/log-for :double)
[3.0 4.25]

; log is now 'fixed' so this call isn't logged
user=> (mean [9 8 6 20]) ;;=> 10.75
user=> (pm/log-for :double)
[3.0 4.25]

In this example we access the log-for the :double key when it contains [3.0 4.25] and this closes it. Further calls of the function don't log data to the key.

We can reset a key back to zero by using the reset-key! function:

; clear the log with pm/reset-key
user=> (pm/reset-key! :double)
user=> (pm/log-for :double)
nil

To see the keys that are currently being logged use pm/keys function:

user=> (pm/keys)
#{:double user/mean :stats}

In this case we're logging three keys.

Postmortem Dump

Aside from spying at a particular point in execution, we can also ask Postmortem to dump all the local variables at that point:

; Example 6: function return values
; we want to see local values
(defn stats
    [fname [height weight] ]
        (let [i 10]
        (println fname "is" height)
        (pm/dump :stats)))

user=> (stats "Bob" [178 68])
Bob is 178
{:fname "Bob", :p__7770 [178 68], :vec__7771 [178 68], :height 178, :weight 68, :i 10}

user=> (pm/log-for :stats)
{:fname "Bob", :p__7770 [178 68], :vec__7771 [178 68], :height 178, :weight 68, :i 10}

As you can see when the stats function is called our dump is called and it gives us all the local variables at that point in time. This is really nice if you're trying to figure out a particular function quickly and is similar to Scope Capture.

Postmortem is a different sort of tool to Hashp and Debux as it focuses on postmortem debugging where you'd be running it to log live system. It's a bit more hassle to use than the other tools for my use-case of 'development in the REPL' as you have to both attach the spy and then access the log, you also don't get the form that was being evaluated. However, it does have a unique and clever trick to make life easier - automated instrumentation!

No hands instrumenting

Rather than putting a spy>> into a function what if we could automatically instrument a function without having to do anything yourself! That's what pi/instrument does for you:

; define a function
(defn mean [xs]
    (/ (double (reduce + xs)) (count xs)))

; tell postmortem you want to instrument it
user=> (pi/instrument `mean) ;;=> [user/mean]

; run the function again
user=> (mean [1 4 5 2])

; get the logs
user=> (pm/log-for `mean)
[{:args ([1 4 5 2])} {:args ([1 4 5 2]), :ret 3.0}]

It automatically gives you a vector with one log for the function starting and one for it returning. The first one is the entry to the function, where the :args key has the arguments that went to the function. For the 'return' entry we get the function args again and a :ret key which is the return value of the function (if it errors it gives you an :err key).

There's basically an order at this point, start by seeing if Hashp will show you what you want to see and if not try Debux. If you can't get it with them then use Postmortem - it's going to shine where you want to debug across a number of functions and record information through the pipeline or over a number of sessions. See the documentation for further advanced capabilities.

Further Resources

  • Notes on Debugging Clojure
    Eli Bendersky's notes cover useful macros and using tools.trace.
  • Clojure development tools
    Jakub Holy's page on Clojure is full of great tools and ideas. Required reading.
  • Debugging in Clojure: Tools
    Ian Truslove's post on debugging Clojure. After you've read this, read the rest of his site!
  • Pimp my REPL
    In homage to "Pimp my Ride" Timo Mihaljov covers his REPL set-up. Covers similar space to my last few posts, but contrasting tool choices.

Final Thoughts

Over the last few posts we've covered the main elements of a REPL-centric workflow. Starting by setting up a Rebel-Readline enabled REPL. In the second post we covered Leiningen, configuring a dev profile and the REPL's tools. Finally, in this post we've covered some observability and debugging tools that we can use to understand our code. I'm sure there are other tools I missed, which ones are great and how do you use them?

We've focused exclusively on using the REPL directly, beyond a certain size working directly in the editor is better. The next challenge is how to connect an editor and the tools available.


Posted in Tech Saturday 16 May 2020
Tagged with tech clojure