[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