“Mostly I just print values. When I’m developing a program I do a tremendous amount of printing”

- Ken Thompson on debugging

Printing values produced by an executing program is a simple but very effective means to understand its behavior. A normal print statement can be transformed into a more powerful debugging tool if we can extend it with certain features.

For example, it would be nice if a print statement used for debugging is able to show the file name along with the line and column number where it was invoked.

It would be informative to show not just the value of a variable, but also its name as used by the program.

The Pyret programming language, a language of choice for programming education, provides the spy statement, which can be thought of as print extended for debugging.

It is not very difficult to implement the spy statement in Clojure as a macro:

(defmacro spy [x & xs]
  (let [f *file*
        m (meta &form)
        msg-prefix (if (seq xs)
                     (str "Spying " x)
        msg (str msg-prefix " (at " f ":" (:line m) ":" (:column m) ")")
        prefix-expr `(println ~msg)]
    (let [obj (if (seq xs) (first xs) x)]
      (if (symbol? obj)
        `(let [msg# (str "  " '~obj ": " ~obj)]
           (println msg#))
        `(do ~prefix-expr (println " " ~obj))))))

The expression (meta &form) enables us to extract the line and column numbers attached to the site of the macro call.

The current file name is bound to *file*. Briefly, &form and *file* contains the information needed to produce the debugging output.

The following usage examples of spy were picked directly from the Pyret documentation:

;; filename: spy/core.clj
(ns spy.core

;; (defmacro spy ....)

;; Spying a variable with a message.
(defn square [x]
  (spy "in square" x)
  (* x x))

(defn cube [x]
  (spy "in cube" x)
  (* x x x))

;; Spying expressions with names.
(defn reverse [lst sofar]
  (spy "length"
       {:lst-length (count lst)
        :sofar-length (count sofar)
        :sum (+ (count lst) (count sofar))})
  (if (seq lst)
    (reverse (rest lst) (cons (first lst) sofar))

(defn -main [& args]
  (let [x 100
        y [1 2 3]]
    (spy x)
    (spy y)
    (square x)
    (cube x)
    (square x)
    (println (reverse y []))))

Running this program will produce output similar to what is shown below:

Spying (at spy/core.clj:39:5)
  x: 100
Spying (at spy/core.clj:40:5)
  y: [1 2 3]
Spying in square (at spy/core.clj:20:3)
  x: 100
Spying in cube (at spy/core.clj:24:3)
  x: 100
Spying in square (at spy/core.clj:20:3)
  x: 100
Spying length (at spy/core.clj:28:3)
  {:lst-length 3, :sofar-length 0, :sum 3}
Spying length (at spy/core.clj:28:3)
  {:lst-length 2, :sofar-length 1, :sum 3}
Spying length (at spy/core.clj:28:3)
  {:lst-length 1, :sofar-length 2, :sum 3}
Spying length (at spy/core.clj:28:3)
  {:lst-length 0, :sofar-length 3, :sum 3}
(3 2 1)

I hope that the spy macro will enhance the development experience of those who love debugging by a “tremendous amount of printing”!

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