Debugging improvements

#1

I’ve been working on some improvements to the debugging features in uLisp, and I would be interested in feedback on them with a view to possibly incorporating them in the next release of uLisp.

Error messages

I’m generally fairly happy with the error reporting in uLisp. The error messages seem clear, and they are generally descriptive, with information about the context and the value causing the problem:

errorformat
errorformat.gif818x84 5.89 KB

For a full list of the error messages, and an explanation of when they can occur, see Error messages.

However, while working on a recent uLisp project (A Lisp compiler for ARM written in Lisp) I became aware of one area in which the current error reporting falls short; it’s often not easy to locate the cause of the error in a large program.

Here’s a rather contrived example:

(defun eqn (x) (* x (/ (- 4 x))))

(defun sq (x) (/ (* (eqn x) (eqn x)) x))

(defun myprog () (dotimes (x 2) (print (sq (+ 3 x)))))

The main program, (myprog) , prints the result of calling sq which in turn calls a function eqn. There’s a bug that causes a runtime error. In current versions of uLisp, running myprog would display this error message:

22925> (myprog)

3 
Error: '/' division by zero
22925>

But it doesn’t help you work out where the division operation is that’s causing the error.

Backtrace

My proposed improvement to uLisp is to provide a backtrace in each error message, which shows in square brackets the sequence of function calls that caused the error:

22925> (myprog)

3 
Error [eqn <- sq <- myprog]: '/' division by zero
22925>

This makes it clear that the error occurred in the user function eqn, and this was called by sq which in turn was called by myprog.

By default I propose to show a call sequence of up to ten functions; this should be enough for most applications.

Compile-time option

if you preferred the way uLisp used to be you could disable the feature with the directive:

#define backtrace

There is no performance penalty, but it uses a small amount of RAM to store the backtrace, which should only be significant on very constrained platforms.

Trace

I’ve also added the ability to display the backtrace from within the break function. For example, suppose you insert a call to break within the eqn function above:

(defun eqn (x) (break) (* x (/ (- 4 x))))

Running myprog will execute the break and put you in the REPL from where you can examine the value of variables such as x :

22922> (myprog)

Break!
22901 : 1> x
3

Previously you could continue execution by typing nil. I propose to add the following options:

Option Description
nil or :c Continue execution
:b Display backtrace
:a Abort

The :b option will display a backtrace in the same format as in the error messages:

22901 : 1> :b
[eqn <- sq <- myprog]

The :a option aborts execution and returns to the main prompt. It’s equivalent to typing :c repeatedly.

For a full description of break, and the other debugging features in uLisp, see Debugging in uLisp.

Feedback

I look forward to hearing feedback about these proposed new features!

#2

Hi David, any improvement in Debugging is most welcome. Since the improvements you mention can be switched off it looks like a win-win situation. Gets my vote.
Regards KeithA

#3

My opinion: Very much appreciated, David - that would help a lot!

#4

I LOVE this idea!!!

I was going to implement it myself but couldn’t figure out a good way how to do that.

One question, will the traceback include tail call eliminated frames?

#5

will the traceback include tail call eliminated frames

The backtrace will include all user function calls, but tail call elimination will be disabled if you choose to have a backtrace.

#6

Some further thoughts about the proposed backtrace feature:

Enabling backtrace

I propose to make the backtrace enabled by default; to disable it you can evaluate:

(backtrace nil)

or to enable it again:

(backtrace t)

You might want to disable it after debugging your program if it takes advantage of tail-call optimisation, because tail-call optimisation is disabled when the backtrace is enabled.

Apart from this, the backtrace has no effect on performance; for example, the tak benchmark gives the same execution time with backtrace enabled.

Anonymous functions

If an error occurs within an anonymous lambda function, such as:

(defun anon (x) ((lambda (i) (expt i -0.5)) x))

the function will be shown as lambda. For example:

22901> (anon -1)
Error [lambda <- anon]: 'expt' invalid result

Recursive functions

If a function calls itself recursively, the backtrace will only show one entry for the function being called; for example, in the function:

(defun loopy (x) (princ x) (delay 1000) (loopy (1+ x)))

If you interrupt execution by typing “~” the error message shows:

22901> (loopy 1)
123456 Error [loopy]: 'delay' escape!

I feel that having multiple entries for the same function would give no useful additional information.

#7

For TCO’ed frames, I propose that the entries where TCO occurred be marked with a number like so:

22901> (loopy 1)
123456 Error [loopy(6)]: 'delay' escape!
#8

Nice idea!

#9

Another thought: since it’s only C function calls that can appear in the “context” section, would it be more appropriate to include them in the backtrace, and do away with the “context” portion? I would also keep the error message as close as possible to the word “error”, so the backtrace might go after the message. Compare:

22901> (anon -1)
Error: invalid result [expt <- lambda <- anon]

versus

22901> (anon -1)
Error [lambda <- anon]: 'expt' invalid result
#10

Good suggestions, thanks - I’ll think about them.

#11

Been a while — any updates? Snags? Concerns?

#12

Thanks for checking!

I’ve decided to work with the backtrace feature myself for a while before finalising it, but it definitely makes debugging programs much easier. Just trying to decide on the details.

David

#13

Thinking about this:

since it’s only C function calls that can appear in the “context” section, would it be more appropriate to include them in the backtrace, and do away with the “context” portion?

Although I agree with the principle of keeping things simple, I think it might be confusing, because the backtrace will only show user-defined functions, whereas the context section shows built-in functions.

I would also keep the error message as close as possible to the word “error”, so the backtrace might go after the message.

Or, perhaps, have the backtrace on a separate line, as it may contain up to seven user-defined function names, which could be quite long:

22901> (anon -1)
[expt <- lambda <- anon]
Error: invalid result

David

#14

Dear David, thank you very much for your efforts in this very relevant direction!

Best wishes.
Anatoly Shcherbakov.