Stumbling Through History
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
;; 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.