Pretty SBCL backtraces

Posted on 2007-12-19 in Lisp
12 comments

Every now and then I see complaints about the stacktraces in SBCL. They contain too little info, or too much info, or are formatted the wrong way, etc. But the backtrace printing isn't really any dark magic, it's just basic Lisp code. If you don't like the default format, just write a new backtrace function that prints something prettier/less cluttered/more informative/etc.

For inspiration, below is one implementation, based on a really quick hack I wrote in answer to a c.l.l post a few weeks ago. In addition to cosmetic changes, it adds a a couple of extra features: printing filenames and line numbers for the frames when possible, and printing the values of local variables when possible. Just call backtrace-with-extra-info in any condition handler where you'd normally call sb-debug:backtrace, or call it from the debugger REPL instead of using the backtrace debugger command.

The code assumes that you've got Swank loaded. For best results, compile your code with (debug 2) or higher.

(defun backtrace-with-extra-info (&key (start 1) (end 20))
  (swank-backend::call-with-debugging-environment
   (lambda ()
     (loop for i from start to (length (swank-backend::compute-backtrace
                                        start end))
           do (ignore-errors (print-frame i))))))
(defun print-frame (i)
  (destructuring-bind (&key file position &allow-other-keys)
      (apply #'append
             (remove-if #'atom
                        (swank-backend:frame-source-location-for-emacs i)))
    (let* ((frame (swank-backend::nth-frame i))
           (line-number (find-line-position file position frame)))
      (format t "~2@a: ~s~%~
                   ~:[~*~;~:[~2:*    At ~a (unknown line)~*~%~;~
                             ~2:*    At ~a:~a~%~]~]~
                   ~:[~*~;    Local variables:~%~{      ~a = ~s~%~}~]"
              i
              (sb-debug::frame-call (swank-backend::nth-frame i))
              file line-number
              (swank-backend::frame-locals i)
              (mapcan (lambda (x)
                        ;; Filter out local variables whose variables we
                        ;; don't know
                        (unless (eql (getf x :value) :<not-available>)
                          (list (getf x :name) (getf x :value))))
                      (swank-backend::frame-locals i))))))
(defun find-line-position (file char-offset frame)
  ;; It would be nice if SBCL stored line number information in
  ;; addition to form path information by default Since it doesn't
  ;; we need to use Swank to map the source path to a character
  ;; offset, and then map the character offset to a line number
  (ignore-errors
   (let* ((location (sb-di::frame-code-location frame))
          (debug-source (sb-di::code-location-debug-source location))
          (line (with-open-file (stream file)
                  (1+ (loop repeat char-offset
                            count (eql (read-char stream) #\Newline))))))
     (format nil "~:[~a (file modified)~;~a~]"
             (= (file-write-date file)
                (sb-di::debug-source-created debug-source))
             line))))

For example on the following code:

(declaim (optimize debug))
(defun foo (x)
  (let ((y (+ x 3)))
    (backtrace)
    (backtrace-with-extra-info)
    (+ x y)))
(defmethod bar ((n fixnum) (y (eql 1)))
  (foo (+ y n)))

The old backtrace would look like:


1: (FOO 4)
2: ((SB-PCL::FAST-METHOD BAR (FIXNUM (EQL 1)))
    #<unused argument>
    #<unused argument>
    3
    1)
3: (SB-INT:SIMPLE-EVAL-IN-LEXENV (BAR 3 1) #<NULL-LEXENV>)

And the new backtrace like:

1: FOO
   At /tmp/testlisp:5
   Local variables:
     X = 4
     Y = 7
2: (SB-PCL::FAST-METHOD BAR (FIXNUM (EQL 1)))
   At /tmp/testlisp:8
   Local variables:
     N = 3
     Y = 1
3: SB-INT:SIMPLE-EVAL-IN-LEXENV
   At /scratch/src/sbcl/src/code/evallisp:93 (file modified)
   Local variables:
     ARG-0 = (BAR 3 1)
     ARG-1 = #<NULL-LEXENV>

An improvement? That's probably in the eye of the beholder, and depends on the codebase and the use cases. For example I can imagine that for large functions showing the values of local variables in the trace would make it way too spammy. But that's besides the point: if the default stacktrace format is making debugging difficult for you, it's not hard to customize it.

Next Game design diary: minimal 18xx train rush game #1 (2010-10-11)
Previous Faster SBCL hash-tables (2007-10-01)

Comments

By David Plumpton on 2007-12-20

Actually, it was the backtraces more than anything else that made me give up on Lisp a couple of years ago. I would get some code starting to run in SBCL, then hit a problem, and I just found the stack traces to be so impenetrable and hostile compared to other languages (Java, Python) that eventually I just gave up.

Even this trace seems to complex. To my mind, there needs to be some version that pretty much just says:

FOO line 42 BAR line 69

etc.

Just try to cut the rest away, if you can.

By Juho on 2007-12-20

I'm not going to cut anything away from those traces, it was just an example for people who have trouble with the current format to roll their own. Anybody with a little Lisp experience will certainly be able to modify that code to show only a format like you want.

I don't think it's a format I'd like, even if didn't always use the Slime debugger with its superior interactive stacktraces.

But thanks for illustrating the "there's too much information" argument, I was afraid people would consider it a strawman :-) For example putting the local variables into the trace was a direct feature request in the c.l.l thread I mentioned.

By lofi on 2007-12-20

I'm not sure the new format is easily grokkable, it gonna mean I have to set my console buffer size right up to debug my current app

are you really sure you're chasing the right fox here?

widening the scope of discussion a little, I'm unsure lisp is really suitable as a working language anymore, the tooling around it is just so anaemic compared to Java

By Juho on 2007-12-20

> are you really sure you're chasing the right fox here?

No, and I don't see how I could've been much more explicit about it.

Every now and then people want backtraces with local variables and line numbers in them. I'm not that somebody, I'm just showing one way of achieving that, or any other backtrace format anybody could want.

I'm not suggesting that this be the default SBCL backtrace format, or anything like that.

By Ignas on 2007-12-21

Thanks, a very nice thing to know.

I would have had a lot of use from it, back when I was not using SLIME (i think there was no SLIME back then). I was not used to the debugger prompt coming up instead of the familiar backtrace that was shown for most of the language I used before.

By Shane on 2007-12-21

This is really cool. I've wondered about the backtraces. Usually, when I'm developing in Common Lisp and I start getting errors, I actually just end up uncommenting lines and relying on unit tests, which just shows how poor my skills are at using SLIME's debugging tools probably. Anyway, I do have a lot of difficulty working with SBCL's stack traces. What's great about this though is now I can actually try to make them suit my needs and expectations. Many thanks for this.

By Juho on 2007-12-21

Shane,

Compile with (debug 2) or higher, and press "v" on a debugger frame in Slime. It'll take you directly to the correct form.

By starseeker on 2007-12-27

Very nice (at least to the eye of this beholder.)

The most important point to me is the one about how sbcl retaining line info by default would be nice. I couldn't agree more - is there any chance of adding that ability in a future sbcl release? Maybe it could even be toggled on/off as a setting if some people wouldn't want it?

By Oisin on 2008-06-22

As a complete Lisp newbie, I really wish the debugger would always display line numbers. I'll have to try the (debug 2) / 'v' trick in the debugger though; it sounds like just the ticket.

p.s. Unicode broken in these blog comments? Seems like it...

By nicktastic on 2009-03-10

Thanks for sharing this trick! I'm new to Lisp and sbcl has been my impl of choice for a number of reasons, but the default stacktrace has been _so frustrating_.

Filename, line number, and cause of failure are the primary data needed to fix a compilation problem, yet they aren't printed by default. PONDEROUS!

Thanks so much.

By Carlo Hamalainen on 2012-03-17

For anyone using a recent version of Slime, change

frame-source-location-for-emacs

to

swank:frame-source-location

due to a renaming in Slime around mid 2009.

By eMBee on 2012-11-18

how would you achieve this without using slime?

Name
Message

As an antispam measure, you need to write a super-secret password below. Today's password is "xyzzy" (without the quotes).

Password

Formatting guidelines for comments: No tags, two newlines can be used for separating paragraphs, http://... is automatically turned into a link.