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>
