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?
Thank you in advance for your help.
On 13-04-05 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?Some function calls don't create stack frame records, so that may be your problem, but then I wouldn't have expected to see "c" there. This may be a bug. 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