[R] Help interpreting output of Rprof
Duncan Murdoch
murdoch at stats.uwo.ca
Mon Oct 22 22:13:46 CEST 2007
On 10/22/2007 2:36 PM, Dieter Best wrote:
> Hello there,
>
> I am not quite sure how to interpret the output of Rprof (in the following the output I was staring at). I was poking around the web a little bit for documentation but without much success. I guess if I want to figure out what takes so long in my code the 2nd table $by.total and the total.pct column (pct = percent) is the most helpful. What does it mean that [ or [.data.frame is taking so much time, and is there something I could do to improve the situation.
I'll try to help, but the documentation in the Writing R Extensions
manual should be your first stop.
The definitions of the 4 columns are:
self.time: how many seconds were spent in that function
self.pct: what percent is this of the overall time. (These numbers
should total 100%, modulo rounding and truncation.)
total.time: how many seconds were spent in that function or the
functions that it called
total.pct: what percentage this is of the total. (These numbers will
typically total much more than 100%, because functions will be counted
for themselves, and for all the functions that call them.)
So look at the functions you wrote that score high in total.pct, because
they are the ones where optimization will have an impact. You may be
able to modify them to avoid calling some of the high cost functions
that you didn't write.
[.data.frame is a known slow function. If execution time matters to
you, don't use it. Convert data frames to matrices, where indexing is
much faster. In your case, this one change could possibly speed up
things by a factor of 2, because you're spending half the execution time
just indexing into data frames.
One other piece of advice: after you identify a possible change, make
it and redo the profiling. [.data.frame calls so many other functions
that if you get rid of it you may drastically change the profile.
Duncan Murdoch
> Thanks,
>
> -- D
>
>
>> summaryRprof(tmp)
> $by.self
> self.time self.pct total.time total.pct
> eval.with.vis 75.92 22.4 339.18 100.0
> [.data.frame 46.28 13.6 186.36 54.9
> structure 31.78 9.4 79.92 23.6
> inherits 27.28 8.0 29.08 8.6
> match 20.38 6.0 53.84 15.9
> names 20.20 6.0 20.20 6.0
> length 9.68 2.9 9.68 2.9
> pmatch 9.02 2.7 10.46 3.1
> [ 8.56 2.5 194.92 57.5
> eval 5.84 1.7 31.02 9.1
> any 5.78 1.7 6.88 2.0
> match.arg 5.68 1.7 40.54 12.0
> is.factor 4.68 1.4 32.28 9.5
> cor 4.66 1.4 67.44 19.9
> [[ 4.32 1.3 13.46 4.0
> stopifnot 4.10 1.2 11.94 3.5
> <Anonymous> 4.08 1.2 4.56 1.3
> deparse 3.86 1.1 23.92 7.1
> [[.data.frame 3.70 1.1 9.14 2.7
> == 3.20 0.9 3.20 0.9
> vector 2.80 0.8 11.94 3.5
> rank 2.40 0.7 22.58 6.7
>> 2.16 0.6 2.16 0.6
> ! 1.92 0.6 1.92 0.6
> %in% 1.86 0.5 25.48 7.5
> switch 1.68 0.5 1.76 0.5
> names<- 1.56 0.5 1.78 0.5
> < 1.54 0.5 1.54 0.5
> .deparseOpts 1.50 0.4 11.98 3.5
> match.call 1.48 0.4 2.84 0.8
> .Call 1.34 0.4 1.34 0.4
> is.na 1.30 0.4 1.30 0.4
> all 1.24 0.4 1.48 0.4
> formals 1.22 0.4 2.46 0.7
> mode 1.22 0.4 1.32 0.4
> sum 1.20 0.4 1.62 0.5
> sys.parent 1.14 0.3 1.14 0.3
> as.character 0.98 0.3 0.98 0.3
> parent.frame 0.96 0.3 0.96 0.3
> attributes<- 0.90 0.3 0.90 0.3
> sys.call 0.86 0.3 1.36 0.4
> list 0.82 0.2 0.82 0.2
> & 0.74 0.2 0.74 0.2
> sys.function 0.58 0.2 1.22 0.4
> attr<- 0.58 0.2 0.58 0.2
> is.logical 0.56 0.2 0.56 0.2
> Rank 0.54 0.2 23.18 6.8
> != 0.54 0.2 0.54 0.2
> : 0.52 0.2 0.52 0.2
> - 0.46 0.1 0.46 0.1
> as.vector 0.44 0.1 0.44 0.1
> .subset2 0.36 0.1 0.36 0.1
> min 0.34 0.1 0.34 0.1
> seq_along 0.34 0.1 0.34 0.1
> max 0.32 0.1 0.32 0.1
> is.data.frame 0.24 0.1 1.72 0.5
> is.character 0.18 0.1 0.18 0.1
> is.matrix 0.18 0.1 0.18 0.1
> oldClass<- 0.18 0.1 0.18 0.1
> is.list 0.16 0.0 0.16 0.0
> ( 0.14 0.0 0.14 0.0
> dim 0.14 0.0 0.14 0.0
> ^ 0.12 0.0 0.12 0.0
> is.pairlist 0.10 0.0 0.10 0.0
> is.null 0.08 0.0 0.08 0.0
> attributes 0.06 0.0 0.06 0.0
> is.atomic 0.06 0.0 0.06 0.0
> baseenv 0.04 0.0 0.04 0.0
> is.call 0.04 0.0 0.04 0.0
> is.name 0.04 0.0 0.04 0.0
> is.expression 0.02 0.0 0.02 0.0
> source 0.00 0.0 339.18 100.0
> $by.total
> total.time total.pct self.time self.pct
> eval.with.vis 339.18 100.0 75.92 22.4
> source 339.18 100.0 0.00 0.0
> [ 194.92 57.5 8.56 2.5
> [.data.frame 186.36 54.9 46.28 13.6
> structure 79.92 23.6 31.78 9.4
> cor 67.44 19.9 4.66 1.4
> match 53.84 15.9 20.38 6.0
> match.arg 40.54 12.0 5.68 1.7
> is.factor 32.28 9.5 4.68 1.4
> eval 31.02 9.1 5.84 1.7
> inherits 29.08 8.6 27.28 8.0
> %in% 25.48 7.5 1.86 0.5
> deparse 23.92 7.1 3.86 1.1
> Rank 23.18 6.8 0.54 0.2
> rank 22.58 6.7 2.40 0.7
> names 20.20 6.0 20.20 6.0
> [[ 13.46 4.0 4.32 1.3
> .deparseOpts 11.98 3.5 1.50 0.4
> stopifnot 11.94 3.5 4.10 1.2
> vector 11.94 3.5 2.80 0.8
> pmatch 10.46 3.1 9.02 2.7
> length 9.68 2.9 9.68 2.9
> [[.data.frame 9.14 2.7 3.70 1.1
> any 6.88 2.0 5.78 1.7
> <Anonymous> 4.56 1.3 4.08 1.2
> == 3.20 0.9 3.20 0.9
> match.call 2.84 0.8 1.48 0.4
> formals 2.46 0.7 1.22 0.4
>> 2.16 0.6 2.16 0.6
> ! 1.92 0.6 1.92 0.6
> names<- 1.78 0.5 1.56 0.5
> switch 1.76 0.5 1.68 0.5
> is.data.frame 1.72 0.5 0.24 0.1
> sum 1.62 0.5 1.20 0.4
> < 1.54 0.5 1.54 0.5
> all 1.48 0.4 1.24 0.4
> sys.call 1.36 0.4 0.86 0.3
> .Call 1.34 0.4 1.34 0.4
> mode 1.32 0.4 1.22 0.4
> is.na 1.30 0.4 1.30 0.4
> sys.function 1.22 0.4 0.58 0.2
> sys.parent 1.14 0.3 1.14 0.3
> as.character 0.98 0.3 0.98 0.3
> parent.frame 0.96 0.3 0.96 0.3
> attributes<- 0.90 0.3 0.90 0.3
> list 0.82 0.2 0.82 0.2
> & 0.74 0.2 0.74 0.2
> attr<- 0.58 0.2 0.58 0.2
> is.logical 0.56 0.2 0.56 0.2
> != 0.54 0.2 0.54 0.2
> : 0.52 0.2 0.52 0.2
> - 0.46 0.1 0.46 0.1
> as.vector 0.44 0.1 0.44 0.1
> .subset2 0.36 0.1 0.36 0.1
> min 0.34 0.1 0.34 0.1
> seq_along 0.34 0.1 0.34 0.1
> max 0.32 0.1 0.32 0.1
> is.character 0.18 0.1 0.18 0.1
> is.matrix 0.18 0.1 0.18 0.1
> oldClass<- 0.18 0.1 0.18 0.1
> is.list 0.16 0.0 0.16 0.0
> ( 0.14 0.0 0.14 0.0
> dim 0.14 0.0 0.14 0.0
> ^ 0.12 0.0 0.12 0.0
> is.pairlist 0.10 0.0 0.10 0.0
> is.null 0.08 0.0 0.08 0.0
> attributes 0.06 0.0 0.06 0.0
> is.atomic 0.06 0.0 0.06 0.0
> baseenv 0.04 0.0 0.04 0.0
> is.call 0.04 0.0 0.04 0.0
> is.name 0.04 0.0 0.04 0.0
> is.expression 0.02 0.0 0.02 0.0
> $sampling.time
> [1] 339.18
>
> __________________________________________________
>
>
>
> [[alternative HTML version deleted]]
>
> ______________________________________________
> R-help at r-project.org mailing list
> https://stat.ethz.ch/mailman/listinfo/r-help
> PLEASE do read the posting guide http://www.R-project.org/posting-guide.html
> and provide commented, minimal, self-contained, reproducible code.
More information about the R-help
mailing list