[SISC-devel] proper stack traces

One of the top complaints I get about SISC from my colleagues is the
lack of good stack traces in errors. That's despite the fact that over
the last few years we have spent a substantial amount of effort on
improving error reporting.

The main difficulty is that much of the information that would be found
on the stack in languages like Java is simply not there due to tail
recursion.

Over the last week I have been working on stack tracer for SISC that
addresses this very problem. Its key features are

- "proper" stack traces, even when using tail recursion and call/cc
- tail-call semantics and safe-for-space guarantees are maintained

The implementation associates a bounded data structure with every
CallFrame. Items are added to this data structure on every
call. Whenever the bound is reached an attempt is made to compact the
collected information by detecting (possibly nested) repetitions, which
typically arise when loops are implemented as tail-recursion.

To give you a flavour of what the result looks like, here's a little
test program:

(define (outer m)
  (if (= m 0)
      (/ 1 0)
      (+ (inner (- m 1)) 0)))

(define (inner m)
  (ping 100 m))

(define (ping n m)
  (if (= n 0)
      (outer m)
      (if (zero? (remainder n 10))
          (pong (- n 1) m)
          (ping (- n 1) m))))

(define (pong n m)
  (if (= n 0)
      (outer m)
      (if (zero? (remainder n 10))
          (ping (- n 1) m)
          (pong (- n 1) m))))

Calling
  (outer 3)
without the stack tracing feature enabled produces the following curt
error:

Error in /: division by zero.
stack-test.scm:12:11: <indeterminate call>
stack-test.scm:4:10: <from call to inner> [Repeated 3 times]

Not only is this rather short on useful information, the second line is
actually completely wrong - it points to the call to 'zero?'.

By contrast, with the new stack tracer we get

Error in /: division by zero
-----------------
stack-test.scm:3:7: <call to />
stack-test.scm:11:7: <call to outer>
5 repetitions of ...
  9 repetitions of ...
    stack-test.scm:14:11: <call to ping>
  stack-test.scm:20:11: <call to ping>
  9 repetitions of ...
    stack-test.scm:21:11: <call to pong>
  stack-test.scm:13:11: <call to pong>
stack-test.scm:7:3: <call to ping>
stack-test.scm:4:10: <call to inner>
------------------
stack-test.scm:11:7: <call to outer>
5 repetitions of ...
  9 repetitions of ...
    stack-test.scm:14:11: <call to ping>
  stack-test.scm:20:11: <call to ping>
  9 repetitions of ...
    stack-test.scm:21:11: <call to pong>
  stack-test.scm:13:11: <call to pong>
stack-test.scm:7:3: <call to ping>
stack-test.scm:4:10: <call to inner>
------------------
stack-test.scm:11:7: <call to outer>
5 repetitions of ...
  9 repetitions of ...
    stack-test.scm:14:11: <call to ping>
  stack-test.scm:20:11: <call to ping>
  9 repetitions of ...
    stack-test.scm:21:11: <call to pong>
  stack-test.scm:13:11: <call to pong>
stack-test.scm:7:3: <call to ping>
stack-test.scm:4:10: <call to inner>
------------------
console:60:1: <call to outer>


This gives us an accurate picture of the entire call chain all the way
from our call to 'outer' at the bottom to the failing call to '/' at the
top. The breaks indicate CallFrame boundaries, i.e. there are actually
only four frames on the stack, most of which contain several nested
tail-recursive loops.


Collecting this information comes at a price - currently a threefold
drop in performance, though this can be improved significantly. Even
with such a performance penalty the feature is perfectly usable during
development, where it matters most. One other problem, shared with the
current error reporter, is that function names won't be displayed when
the operator position in a call is a lexical variable. Note that, in a
way, this is actually the correct behaviour: a stack trace, in most
languages at least, contains *source locations*, not *call details*.

By default the stack tracer is turned off. It is turned on by setting
the sisc.maxStackTraceDepth static configuration parameter to a non-zero
value. A value of 16 works fine for me in most cases; large values allow
collection of more information but carry a large performance penalty,
small values result in some call information being lost - the stack
trace output indicates when that has happened.

The stack tracer does not require the heap or other scheme code to be
compiled in any special way. In other words, switching the tracer on/off
is just a matter of setting the aforementioned configuration parameter
on start up. Good results depend on source location information to be
available, just as in the current system.


None of the above is checked in yet, and I doubt it will make it into
the upcoming stable release. I would like to hear what people think of
this stack tracer though. Would you find it useful? Have I missed any
important feature? I am also interested in code examples that produce
less-than-helpful error traces in previous/current SISC releases, so I
can try the new stack tracer on these examples.


Matthias