В R есть встроенная утилита для профилирования производительности и памяти — Rprof. Наберите в консоли ?Rprof, чтобы узнать о ней больше.

Профайлер работает так:

запускаете профайлер, вызывая Rprof и передавая имя файла, где будут храниться данные профилирования
вызываете функции R, которые хотите проанализировать
вызываете Rprof(NULL), чтобы остановить профайлер
анализируете файл, созданный Rprof, как правило, с помощью summaryRprof

Например:

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

Результат будет выглядеть примерно так:

$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

Много информации!

Примечание: sample.interval = 0.02 определяет частоту, с которой Rprofile анализирует стек вызовов и производит измерения. Т.о. Rprofile работает только через опрос. Следовательно, summaryRprof может отличаться каждый раз, когда вы профилируете код. Могут быть не только небольшие отличия в числах, но и, например, недостающие элементы. Скажем, потому что в один из запусков измерение было случайно сделано во время выполнения кода, а при другом запуске выполнение произошло между двумя измерениями.

Показательный пример профилирования

Давайте рассмотрим показательный пример. Допустим, есть следующие функции:

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)
}

Да, ужасно и бессмысленно, но они прекрасно подходят для этого примера: их выполнение занимает определенное время.

Итак, давайте профилировать:

Do_1

 :

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

Что будет выглядеть так:

$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

Отлично. Можно увидеть, что combn занимает около трех четвертей времени выполнения, а paste — только одну четверть.

Погодите-ка: matrix? Откуда это берется? Эта функция должна вызываться или внутри combn, или paste. Не проблема, поскольку matrix занимает только 2,3% общего времени. Но все равно интересно разобраться, правда?

Анализ данных профилирования с prof.tree

Пакет prof.tree Артема Клевцова, доступный на CRAN или на github, предоставляет другой способ анализа этих данных. Он позволяет отобразить данные профилирования в виде дерева:

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

Результат выглядит примерно так:

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

Сюрприз! Matrix вызывается из combn, а не из paste!

Обратите внимание: pr — структура data.tree, так что для нее доступны все операции data.tree. Например, можно собрать информацию по конкретным функциям (по имени):

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

SumByFunction("combn")

И так же, как и выше, это даст нам 73.56%.

Также можно ограничить количество выводимых вершин, удалив все поддеревья с процентом, превышающим, скажем, 5%:

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

Вот результат:

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

Или можно использовать графический инструмент data.tree, чтобы визуализировать это:

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)

График будет выглядеть примерно так:

Профилирование в R