[Rd] why does do_stop call R_GetTraceback ?

[Andrew Piskorski]

I'm using:
  R 2.15.1 (beta), 2012-06-11, svn.rev 59557, x86_64-unknown-linux-gnu
And I normally use:
  options("error"=recover)

I recently ran into a problem where when my code called stop(),
recover() was incredibly slow (hours) because it was trying to deparse
an extremely large call.  I worked around that by instead using my own
recover function which avoids deparsing anything large.  (Perhaps it
would be better to instead make the deparsing much faster, but I don't
know how to do that.)

However, now I find that when I'm DONE debugging and exit my recover
function, R still sits there using 100% cpu for another 41 seconds
before finishing and returning me to the top-level interactive prompt.
I wondered why...  Rprof() seems to say that all the time is being
taken in stop().

AFAICT, in this case stop() is basically just doing this:

  .Internal(stop(as.logical(TRUE), .makeMessage(..., domain=NULL)))

where the "..." is just the single string I passed to stop(), e.g.,
stop("This code is broken.").

So next, after exiting (my hacked version of) recover(), and while
stop() was still trying to finish up, I attached gdb to my R process.
I've appended the relevant part of the (long) backtrace below.

As you can see, R seems to have been busy calling R_GetTraceback() and
a bunch of subsidiary deparse functions.  But, at that point I'm done
with recover(), and when stop() finally finishes NOTHING else has been
printed out - no additional traceback, nothing.  So why are we calling
jump_to_top_ex() with traceback=TRUE, what good does the call to
R_GetTraceback() do?

That jump_to_top_ex() code only calls R_GetTraceback() when
R_Interactive or haveHandler are true.  I am certainly running
interactively here, and I did define a handler with options("error"=).
But AFAICT, my handler makes no use whatsoever of any of the work done
by R_GetTraceback().  In fact, I don't see any way it could even if I
wanted it to.  And if I remove my handler with options("error"=NULL),
I STILL get no additional "trace back" output at all.

So it looks to me as if calling jump_to_top_ex() with traceback=TRUE
and spending the extra 41 seconds in R_GetTraceback() NEVER does
anything useful!  Is this actually true, or does R_GetTraceback() have
some important side effect that I'm unaware of?

Thanks for your help!


(gdb) bt
#0  vector2buff (s=0xba73ed0, d=0x7fffa18d4a00)
    at ../../../src/main/deparse.c:1298
#1  deparse2buff (s=0xba73ed0, d=0x7fffa18d4a00)
    at ../../../src/main/deparse.c:1123
#2  0x00007ff28807034f in vec2buff (v=<value optimized out>, d=0x7fffa18d4a00)
    at ../../../src/main/deparse.c:1402
#3  0x00007ff28806ea20 in deparse2buff (s=0xba734d0, d=0x7fffa18d4a00)
    at ../../../src/main/deparse.c:753
#4  0x00007ff28807034f in vec2buff (v=<value optimized out>, d=0x7fffa18d4a00)
    at ../../../src/main/deparse.c:1402
#5  0x00007ff28806ea20 in deparse2buff (s=0xed9e350, d=0x7fffa18d4a00)
    at ../../../src/main/deparse.c:753
#6  0x00007ff28807034f in vec2buff (v=<value optimized out>, d=0x7fffa18d4a00)
    at ../../../src/main/deparse.c:1402
#7  0x00007ff28806ea20 in deparse2buff (s=0xed9c818, d=0x7fffa18d4a00)
    at ../../../src/main/deparse.c:753
#8  0x00007ff28806e40c in args2buff (arglist=0xd90b930, 
    lineb=<value optimized out>, formals=0, d=0x7fffa18d4a00)
    at ../../../src/main/deparse.c:1438
#9  0x00007ff28806e822 in deparse2buff (s=0xd90b8c0, d=0x7fffa18d4a00)
    at ../../../src/main/deparse.c:1108
#10 0x00007ff2880706f9 in deparse2 (call=<value optimized out>, abbrev=FALSE, 
    cutoff=<value optimized out>, backtick=<value optimized out>, opts=65, 
    nlines=-1) at ../../../src/main/deparse.c:484
#11 deparse1WithCutoff (call=<value optimized out>, abbrev=FALSE, 
    cutoff=<value optimized out>, backtick=<value optimized out>, opts=65, 
    nlines=-1) at ../../../src/main/deparse.c:221
#12 0x00007ff2880a07b5 in R_GetTraceback (skip=0)
    at ../../../src/main/errors.c:1312
#13 0x00007ff2880a347a in jump_to_top_ex (traceback=TRUE, 
    tryUserHandler=<value optimized out>, processWarnings=FALSE, 
    resetConsole=TRUE, ignoreRestartContexts=13368712)
    at ../../../src/main/errors.c:837
#14 0x00007ff2880a1ba9 in verrorcall_dflt (call=0x28ea1c0, 
    format=<value optimized out>, ap=<value optimized out>)
    at ../../../src/main/errors.c:663
#15 0x00007ff2880a239e in Rf_errorcall (call=<value optimized out>, 
    format=<value optimized out>) at ../../../src/main/errors.c:698
#16 0x00007ff2880a25c2 in do_stop (call=<value optimized out>, 
    op=<value optimized out>, args=0x10ecae78, rho=<value optimized out>)
    at ../../../src/main/errors.c:1095
[...]
#79 0x0000000000400819 in _start ()

-- 
Andrew Piskorski <atp at piskorski.com>