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 <a...@piskorski.com> ______________________________________________ R-devel@r-project.org mailing list https://stat.ethz.ch/mailman/listinfo/r-devel