I was noticing some Lisp code I was writing was getting slower and slower the more I added to it. Normally, this means one is writing idiotic codes and while that may be the problem here, I am a firm believer of denial and looked the other way.

Instead, I profiled my code using some off the shelf directions in the SBCL manual.

What I found was intriguing. Basically, I was spending inordinate amounts of time deep inside some internal function of FORMAT. This was quite surprising to me because while I was printing debugging stuff out for sure, there just wasn't enough output text to justify such profiling numbers.

After some serious thought, I traced the cause to this macro call I had written:

(defmacro emit (s fmt &rest args)                                       ; Wrong!
  `(when *debug-output*
     (format ,s (concatenate 'string "DEBUG: " ,fmt) ,@args)
     (finish-output)))

The intention of this macro was that I want to see the output when there is a valid stream, and not to see it when there is a nil stream, or the *debug-output* special variable was nil. I didn't want to keep writing the template of checking the *debug-output* variable, so I wrote the macro. This was like the tenth function I wrote when I started my project and didn't think anything of it...

It turns out after a while of writing that I had hundreds of these calls, all using a nil stream, in my source codes. I'd set the stream to t or nil in each individual emit invocation depending upon what I was testing or debugging to see output or not. Can you begin to see what is wrong? It turns out that I was calling format with a nil stream (often in tight loops) and simply throwing away the prettily formatted string right into the garbage collector. I didn't see the output and it cost me an arm and a leg to not see any output!

What I really wanted was that when nil is passed to the emit function, the debugging output expression should vanish from the code stream. When I mean vanish, I mean not even a function call there to cost me something. A good way to make something vanish is have it become a (progn) expression which the compiler will throw out since it does nothing.

Starting from that thought, here is my altered emit macro:

(defmacro emit (s fmt &rest args)
  (if (null s)
      `(progn)
      `(when *debug-output*
         (format ,s (concatenate 'string "DEBUG: " ,fmt) ,@args)
         (finish-output))))

Now, I can actually enforce the vanishing of the debugging output (and even the computation cost of the arguments!). I put the new macro into my codes, recompiled, reprofiled, and was very pleased.

EDIT: Some weeks later, after reading more about what macros are legally able to return, it dawns upon me that (progn) evaluates to NIL and I can use this to my benefit. Since the returned NIL from a macro expansion is precisely the same NIL that a (progn) could return. This means I can do this new version instead which is slightly cleaner.

(defmacro emit (s fmt &rest args)
  (unless (null s)
    `(when *debug-output*
       (format ,s (concatenate 'string "DEBUG: " ,fmt) ,@args)
       (finish-output))))

Upon reflection, it is a little sad that the defmacro must return a value since it changes the return value of this kind of code:

;; The initial code
* (let ((a 42)) 
    a)
42

;; And I put in a debugging line to print out a...
* (let ((a 42)) 
    a 
    (emit nil "a = ~A~%" a))
NIL

Oops! I'll need to remember this until I figure out how to make the (emit ...) call completely disappear. I suppose I could use conditional reading with #+ and #-, but it seems an dirty solution to type that for hundreds of locations...

End of Line.