[Rd] why does do_stop call R_GetTraceback ?

From: Andrew Piskorski <atp_at_piskorski.com>
Date: Wed, 21 Nov 2012 21:05:46 -0500


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>

______________________________________________
R-devel_at_r-project.org mailing list
https://stat.ethz.ch/mailman/listinfo/r-devel
Received on Thu 22 Nov 2012 - 02:13:31 GMT

This quarter's messages: by month, or sorted: [ by date ] [ by thread ] [ by subject ] [ by author ]

All messages

Archive maintained by Robert King, hosted by the discipline of statistics at the University of Newcastle, Australia.
Archive generated by hypermail 2.2.0, at Fri 23 Nov 2012 - 01:30:52 GMT.

Mailing list information is available at https://stat.ethz.ch/mailman/listinfo/r-devel. Please read the posting guide before posting to the list.

list of date sections of archive