Profiling in R

R has a built-in performance and memory profiling utility, Rprof. Type in the console ?Rprof to learn more about it.

The profiler works like this:

1. run the profiler by calling Rprof and passing the name of the file where the profiling data will be stored
2. call R functions you want to analyze
3. call Rprof(NULL) to stop the profiler
4. analyze the file created by Rprof, usually with the help of summaryRprof

For example:

 Rprof(tmp <- tempfile()) example(glm) Rprof() summaryRprof(tmp) unlink(tmp) 

The result will look something like this:

 $by.self self.time self.pct total.time total.pct "str.default" 0.02 14.29 0.10 71.43 "deparse" 0.02 14.29 0.04 28.57 "as.name" 0.02 14.29 0.02 14.29 "formals" 0.02 14.29 0.02 14.29 "make.names" 0.02 14.29 0.02 14.29 "parent.frame" 0.02 14.29 0.02 14.29 "pmatch" 0.02 14.29 0.02 14.29 $by.total total.time total.pct self.time self.pct "eval" 0.14 100.00 0.00 0.00 "withVisible" 0.14 100.00 0.00 0.00 "str.default" 0.10 71.43 0.02 14.29 "<Anonymous>" 0.10 71.43 0.00 0.00 "capture.output" 0.10 71.43 0.00 0.00 "doTryCatch" 0.10 71.43 0.00 0.00 "evalVis" 0.10 71.43 0.00 0.00 ".rs.valueContents" 0.10 71.43 0.00 0.00 ".rs.valueFromStr" 0.10 71.43 0.00 0.00 "str" 0.10 71.43 0.00 0.00 "try" 0.10 71.43 0.00 0.00 "tryCatch" 0.10 71.43 0.00 0.00 "tryCatchList" 0.10 71.43 0.00 0.00 "tryCatchOne" 0.10 71.43 0.00 0.00 "do.call" 0.08 57.14 0.00 0.00 "strSub" 0.08 57.14 0.00 0.00 "deparse" 0.04 28.57 0.02 14.29 "example" 0.04 28.57 0.00 0.00 "FUN" 0.04 28.57 0.00 0.00 "lapply" 0.04 28.57 0.00 0.00 "match" 0.04 28.57 0.00 0.00 "source" 0.04 28.57 0.00 0.00 "as.name" 0.02 14.29 0.02 14.29 "formals" 0.02 14.29 0.02 14.29 "make.names" 0.02 14.29 0.02 14.29 "parent.frame" 0.02 14.29 0.02 14.29 "pmatch" 0.02 14.29 0.02 14.29 "anova" 0.02 14.29 0.00 0.00 "anova.glm" 0.02 14.29 0.00 0.00 "data.frame" 0.02 14.29 0.00 0.00 "deParse" 0.02 14.29 0.00 0.00 ".deparseOpts" 0.02 14.29 0.00 0.00 ".getXlevels" 0.02 14.29 0.00 0.00 "glm" 0.02 14.29 0.00 0.00 "%in%" 0.02 14.29 0.00 0.00 "match.call" 0.02 14.29 0.00 0.00 "mode" 0.02 14.29 0.00 0.00 "NextMethod" 0.02 14.29 0.00 0.00 "paste" 0.02 14.29 0.00 0.00 "sapply" 0.02 14.29 0.00 0.00 "str.data.frame" 0.02 14.29 0.00 0.00 "summary" 0.02 14.29 0.00 0.00 "%w/o%" 0.02 14.29 0.00 0.00 $sample.interval [1] 0.02 $sampling.time [1] 0.14 

A lot of information!

Note: sample.interval = 0.02 determines the frequency with which Rprofile analyzes the call stack and makes measurements. So Rprofile works only through a poll. Therefore, the summaryRprof may differ each time you profile the code. There can be not only small differences in numbers, but also, for example, missing elements. Let's say, because in one of the launches a measurement was accidentally done during the execution of the code, and with another launch, the execution occurred between two measurements.
')

Illustrative profiling example

Let's look at a case in point. Suppose there are the following functions:

 Do_1 <- function() { combn(1:20, 5) for (i in 1:15) Do_2() for (i in 1:25) Do_4() } Do_2 <- function() { combn(1:15, 5) for (i in 1:5) Do_3() } Do_3 <- function() { combn(1:14, 5) for (i in 1:20) Do_4() } Do_4 <- function() { paste(1:1000) combn(1:11, 5) } 

Yes, terrible and senseless, but they are perfect for this example: their implementation takes some time.

So let's profile:

 Do_1 : Rprof(tmp <- tempfile()) Do_1() Rprof(NULL) summaryRprof(tmp) 

What will look like this:

 $by.self self.time self.pct total.time total.pct "combn" 1.24 71.26 1.28 73.56 "paste" 0.46 26.44 0.46 26.44 "matrix" 0.04 2.30 0.04 2.30 $by.total total.time total.pct self.time self.pct "Do_1" 1.74 100.00 0.00 0.00 "Do_2" 1.72 98.85 0.00 0.00 "Do_3" 1.68 96.55 0.00 0.00 "Do_4" 1.48 85.06 0.00 0.00 "combn" 1.28 73.56 1.24 71.26 "paste" 0.46 26.44 0.46 26.44 "matrix" 0.04 2.30 0.04 2.30 

Fine. You can see that combn takes about three quarters of the execution time, and paste only one quarter.

Wait a minute: matrix? Where does this come from? This function must be called either inside combn or paste. Not a problem, since matrix takes only 2.3% of the total time. But it's still interesting to find out, right?

Analysis of profiling data with prof.tree

Artem Klevtsov's prof.tree package, available on CRAN or on github , provides another way to analyze this data. It allows you to display profiling data in a tree view:

 library(prof.tree) pr <- prof.tree(tmp) print(pr, limit = NULL) 

The result looks like this:

 levelName real percent env 1 calls 1.74 100.0 % 2 °--Do_1 1.74 100.0 % R_GlobalEnv 3 ¦--Do_2 1.72 98.9 % R_GlobalEnv 4 ¦ ¦--Do_3 1.68 96.6 % R_GlobalEnv 5 ¦ ¦ ¦--combn 0.22 12.6 % utils 6 ¦ ¦ ¦ °--matrix 0.02 1.1 % base 7 ¦ ¦ °--Do_4 1.46 83.9 % R_GlobalEnv 8 ¦ ¦ ¦--combn 1.02 58.6 % utils 9 ¦ ¦ ¦ °--matrix 0.02 1.1 % base 10 ¦ ¦ °--paste 0.44 25.3 % base 11 ¦ °--combn 0.04 2.3 % utils 12 °--Do_4 0.02 1.1 % R_GlobalEnv 13 °--paste 0.02 1.1 % base 

Surprise! Matrix is ​​called from combn, not paste!

Note: pr is a data.tree structure, so that all data.tree operations are available for it. For example, you can collect information on specific functions (by name):

 library(data.tree) SumByFunction <- function(name) { sum(pr$Get("real", filterFun = function(node) node$name == name))/pr$real } SumByFunction("combn") 

And just as above, it will give us 73.56%.

You can also limit the number of displayed vertices by deleting all subtrees with a percentage greater than, say, 5%:

 print(pr, limit = NULL, pruneFun = function(x) x$percent > 0.05) 

Here is the result:

 levelName real percent env 1 calls 1.74 100.0 % 2 °--Do_1 1.74 100.0 % R_GlobalEnv 3 °--Do_2 1.72 98.9 % R_GlobalEnv 4 °--Do_3 1.68 96.6 % R_GlobalEnv 5 ¦--combn 0.22 12.6 % utils 6 °--Do_4 1.46 83.9 % R_GlobalEnv 7 ¦--combn 1.02 58.6 % utils 8 °--paste 0.44 25.3 % base 

Or you can use the data.tree graphic tool to visualize this:

 cols <- colorRampPalette(c("green", "red"))(101) SetNodeStyle(pr, style = "filled,rounded", shape = "box", fontname = "helvetica", fillcolor = function(node) cols[round(node$percent * 100) + 1], tooltip = function(node) node$real) plot(pr) 

The graph will look something like this: