[R] line profiling

[Duncan Murdoch]

On 05/04/2013 6:39 AM, Florent D. wrote:
> Hello,
>
> This is about the new "line profiling" feature in R 3.0.0. As I was
> testing it, I find the results somewhat disappointing so I'd like to
> get your opinion.
>
> I put some poorly written code in a test.R file, here are the contents:
>
> double <- function(x) {
>    out <- c()
>    for (i in x) {
>      out <- c(out, 2*i)   # line 4
>    }
>    return(out)
> }
>
> Then this how I source the file and run a profile:
>
> source("test.R", keep.source = TRUE)
> Rprof("test.profile", line.profiling=TRUE)
> y <- double(1:20000)
> Rprof(NULL)
> summaryRprof("test.profile", lines = "both")
>
> The relevant part of the output is:
>
> $by.total
>           total.time total.pct self.time self.pct
> "double"       0.98    100.00      0.00     0.00
> "c"            0.92     93.88      0.92    93.88
> test.R#4       0.06      6.12      0.06     6.12
>
> My problem is I was expecting test.R#4 (line 4 of my file) to show up
> somewhere between "c" and "double", because "c" is called on line #4
> of my file, and line #4 is inside the body of the "double" function.
> If I look at the "test.profile" where I told Rprof() to record, there
> are a lot of
>
> "c" "double"
>
> records while I was hoping to find
>
> "c" 1#4 "double"
>
> Can someone please explain why, when the profiler records "c", it does
> not record the extra information that "c" was called on line 4? Is it
> not possible to know? Is it a choice the developers made? An
> oversight?
>

Yes, this looks like it was a bug.  The problem is that built-in 
functions like "c" don't necessarily create a stack context, so they are 
handled specially during profiling.  With the original version, the line 
number of the call to "c" was recorded twice, both as the line where "c" 
was called, and as the line within the "c" function (which is bogus, "c" 
has no R code at all).  The bug fix removed both, but should only have 
removed the latter one.

If it survives some more testing, I'll put the fix for this into R-patched.

Duncan Murdoch