R:Профилирование кода — различия между версиями

Материал Psylab.info - энциклопедии психодиагностики
Перейти к: навигация, поиск
м (→‎Функция proftable)
м (→‎Функция proftable)
 
(не показаны 3 промежуточные версии этого же участника)
Строка 1: Строка 1:
 +
<!-- R:Профилирование кода -->
 +
 +
 +
 
{{CC-BY-4.0|author=автором Артём Клевцов}}
 
{{CC-BY-4.0|author=автором Артём Клевцов}}
  
Строка 15: Строка 19:
 
В качестве примера ниже представлены шаги процесса профилирования функции, которая рассчитывает первичные описательные статистики (среднее, медиану, стандартное отклонение, минимум и максимум) по сгенерированным <math>10^6</math> нормально распределённым значениям.
 
В качестве примера ниже представлены шаги процесса профилирования функции, которая рассчитывает первичные описательные статистики (среднее, медиану, стандартное отклонение, минимум и максимум) по сгенерированным <math>10^6</math> нормально распределённым значениям.
  
−
{{r-code|code=
+
{{r-code|code=<nowiki>x <- rnorm(10^6)
−
<nowiki>> x <- rnorm(10^6)
+
</nowiki>}}
−
</nowiki>
+
−
}}
+
  
 
Объявим данную функцию:
 
Объявим данную функцию:
  
−
{{r-code|code=
+
{{r-code|code=<nowiki>desc <- function(x) {
−
<nowiki>desc <- function(x) {
+
 
   n <- length(x)
 
   n <- length(x)
 
   mean <- mean(x)
 
   mean <- mean(x)
Строка 32: Строка 33:
 
   return(c(n, mean, median, sd, min, max))
 
   return(c(n, mean, median, sd, min, max))
 
}
 
}
−
</nowiki>
+
</nowiki>}}
−
}}
+
  
 
Шаг 1. Создание временного файла для записи лога профилирования (необязательно):
 
Шаг 1. Создание временного файла для записи лога профилирования (необязательно):
  
−
{{r-code|code=
+
{{r-code|code=<nowiki>tmp.log <- tempfile(pattern = "rprof-", fileext = ".log")
−
<nowiki>> tmp.log <- tempfile(pattern = "prof-", fileext = ".log")
+
</nowiki>}}
−
</nowiki>
+
−
}}
+
  
 
Посмотреть путь и имя временного файла лога можно, введя имя переменной <code>tmp.log</code>:
 
Посмотреть путь и имя временного файла лога можно, введя имя переменной <code>tmp.log</code>:
  
−
{{r-code|code=
+
{{r-code|code=<nowiki>tmp.log
−
<nowiki>> tmp.log
+
#> [1] "/tmp/Rtmp1kJ8SI/rprof-44673946768c.log"
−
[1] "/tmp/RtmpAvhCfO/prof-23b61d761805.log"
+
</nowiki>}}
−
</nowiki>
+
−
}}
+
  
 
Шаг 2. Собственно процедура профилирования:
 
Шаг 2. Собственно процедура профилирования:
  
−
{{r-code|code=
+
{{r-code|code=<nowiki># Включаем профилирование
−
<nowiki># Включаем профилирование
+
Rprof(tmp.log)
−
> Rprof(tmp.log)
+
 
# Выполняем код
 
# Выполняем код
−
> for (i in seq_len(100))
+
for (i in seq_len(100))
−
+  invisible(desc(x))
+
    invisible(desc(x))
 
# отключаем профилирование
 
# отключаем профилирование
−
> Rprof(NULL)
+
Rprof(NULL)
−
</nowiki>
+
</nowiki>}}
−
}}
+
  
 
Шаг 3. Вывод результатов:
 
Шаг 3. Вывод результатов:
  
−
{{r-code|code=
+
{{r-code|code=<nowiki>summaryRprof(tmp.log)
−
<nowiki>> summaryRprof(tmp.log)
+
</nowiki>}}
−
</nowiki>
+
−
}}
+
  
 
Шаг 4. Удаляем временный файл:
 
Шаг 4. Удаляем временный файл:
  
−
{{r-code|code=
+
{{r-code|code=<nowiki>unlink(tmp.log)
−
<nowiki>> unlink(tmp.log)
+
</nowiki>}}
−
</nowiki>
+
−
}}
+
  
 
Рассмотрим результаты профилирования функции <code>desc()</code>:
 
Рассмотрим результаты профилирования функции <code>desc()</code>:
  
−
{{r-code|code=
+
{{r-code|code=<nowiki>summaryRprof(tmp.log)
−
<nowiki>> summaryRprof(tmp.log)
+
#> $by.self
−
$by.self
+
#>               self.time self.pct total.time total.pct
−
               self.time self.pct total.time total.pct
+
#> "sort.int"          3.94   66.33       4.32     72.73
−
"sort.int"          2.54   52.70       3.04     63.07
+
#> ".Call"            0.50    8.42       0.50      8.42
−
"is.na"            0.70    14.52       0.70    14.52
+
#> "is.na"            0.48     8.08       0.48     8.08
−
".Call"            0.44     9.13       0.44     9.13
+
#> "any"              0.34     5.72       0.34     5.72
−
"min"              0.38     7.88       0.38     7.88
+
#> "min"              0.32    5.39       0.32      5.39
−
"any"              0.32    6.64       0.32      6.64
+
#> "max"              0.26    4.38       0.26      4.38
−
"max"              0.26    5.39       0.26      5.39
+
#> "mean.default"      0.06     1.01       0.06     1.01
−
"mean.default"      0.18     3.73       0.18     3.73
+
#> "mean"              0.02    0.34      4.40    74.07
−
 
+
#> "sys.parent"        0.02    0.34      0.02      0.34
−
$by.total
+
#>
−
                total.time total.pct self.time self.pct
+
#> $by.total
−
"desc"                 4.82   100.00      0.00    0.00
+
#>                      total.time total.pct self.time self.pct
−
"median"               3.56     73.86     0.00    0.00
+
#> "block_exec"               5.94   100.00      0.00    0.00
−
"median.default"      3.56     73.86     0.00    0.00
+
#> "call_block"               5.94    100.00      0.00     0.00
−
"mean"                 3.22     66.80     0.00    0.00
+
#> "evaluate"                  5.94    100.00     0.00    0.00
−
"sort.int"             3.04     63.07     2.54    52.70
+
#> "evaluate_call"            5.94    100.00      0.00    0.00
−
"sort"                 3.04     63.07     0.00    0.00
+
#> "in_dir"                    5.94    100.00      0.00    0.00
−
"sort.default"         3.04     63.07     0.00    0.00
+
#> "knit"                      5.94    100.00      0.00    0.00
−
"is.na"               0.70     14.52     0.70    14.52
+
#> "process_file"              5.94    100.00      0.00    0.00
−
".Call"               0.44     9.13     0.44     9.13
+
#> "process_group"            5.94    100.00      0.00    0.00
−
"sd"                   0.44     9.13     0.00    0.00
+
#> "process_group.block"      5.94    100.00      0.00     0.00
−
"var"                 0.44     9.13     0.00    0.00
+
#> "withCallingHandlers"      5.94    100.00     0.00    0.00
−
"min"                 0.38     7.88     0.38     7.88
+
#> "desc"                     5.92     99.66     0.00    0.00
−
"any"                 0.32      6.64     0.32    6.64
+
#> "eval"                      5.92    99.66     0.00    0.00
−
"max"                 0.26      5.39     0.26    5.39
+
#> "handle"                    5.92    99.66      0.00    0.00
−
"mean.default"         0.18     3.73     0.18     3.73
+
#> "withVisible"              5.92     99.66     0.00    0.00
−
 
+
#> "median"                   4.78     80.47     0.00    0.00
−
$sample.interval
+
#> "median.default"           4.78     80.47     0.00    0.00
−
[1] 0.02
+
#> "mean"                      4.40    74.07      0.02    0.34
−
 
+
#> "sort.int"                  4.32    72.73      3.94    66.33
−
$sampling.time
+
#> "sort"                      4.32    72.73      0.00     0.00
−
[1] 4.82
+
#> "sort.default"              4.32    72.73     0.00    0.00
−
</nowiki>
+
#> ".Call"                     0.50     8.42     0.50     8.42
−
}}
+
#> "sd"                       0.50     8.42     0.00    0.00
 +
#> "var"                       0.50     8.42     0.00    0.00
 +
#> "is.na"                     0.48     8.08     0.48     8.08
 +
#> "any"                       0.34      5.72      0.34    5.72
 +
#> "min"                      0.32      5.39     0.32    5.39
 +
#> "max"                       0.26      4.38     0.26    4.38
 +
#> "mean.default"             0.06     1.01     0.06     1.01
 +
#> "sys.parent"                0.02      0.34      0.02    0.34
 +
#> "<Anonymous>"              0.02      0.34      0.00    0.00
 +
#> "formals"                  0.02      0.34      0.00    0.00
 +
#> "match.arg"                0.02      0.34      0.00    0.00
 +
#> "sink"                      0.02      0.34      0.00    0.00
 +
#> "sys.function"              0.02      0.34      0.00    0.00
 +
#>
 +
#> $sample.interval
 +
#> [1] 0.02
 +
#>
 +
#> $sampling.time
 +
#> [1] 5.94
 +
</nowiki>}}
  
 
Результатом подобных операций является 2 таблицы, отсортированные по разным основаниям: по времени выполнения функции (<code>self.time</code>) и общему времени выполнения функции (<code>total.time</code>). В столбцах представлены абсолютные и относительные (в процентах) показатели времени выполнения.
 
Результатом подобных операций является 2 таблицы, отсортированные по разным основаниям: по времени выполнения функции (<code>self.time</code>) и общему времени выполнения функции (<code>total.time</code>). В столбцах представлены абсолютные и относительные (в процентах) показатели времени выполнения.
Строка 121: Строка 130:
 
При профилировании скриптов включение опции <code>line.profiling</code> проставляет номера строк в которых производился вызов, что позволяет проанализировать производительность всего кода:  
 
При профилировании скриптов включение опции <code>line.profiling</code> проставляет номера строк в которых производился вызов, что позволяет проанализировать производительность всего кода:  
  
−
{{r-code|code=
+
{{r-code|code=<nowiki>Rprof(tmp.log, line.profiling = TRUE)
−
<nowiki>> Rprof(tmp.log, line.profiling = TRUE)
+
source("/path/scritpt.R")
−
> source("/path/scritpt.R")
+
Rprof(NULL)
−
> Rprof(NULL)
+
summaryRprof(tmp.log)
−
> summaryRprof(tmp.log)
+
unlink(tmp.log)
−
> unlink(tmp.log)
+
</nowiki>}}
−
</nowiki>
+
−
}}
+
  
 
== Пакет {{r-package|proftools}} ==
 
== Пакет {{r-package|proftools}} ==
Строка 134: Строка 141:
 
Также может оказаться полезной функция <code>flatProfile()</code> из пакета {{r-package|proftools}}. Данная функция выводит таблицу, сходную с таблицей «by.total» возвращаемую функцией <code>summaryRprof()</code>, в одну и сортирует их по общему времени выполнения в процентах или по времени выполнения функции в процентах, если указать <code>byTotal = FALSE</code>:
 
Также может оказаться полезной функция <code>flatProfile()</code> из пакета {{r-package|proftools}}. Данная функция выводит таблицу, сходную с таблицей «by.total» возвращаемую функцией <code>summaryRprof()</code>, в одну и сортирует их по общему времени выполнения в процентах или по времени выполнения функции в процентах, если указать <code>byTotal = FALSE</code>:
  
−
{{r-code|code=
+
{{r-code|code=<nowiki>flatProfile(readProfileData(tmp.log))
−
<nowiki>> library(proftools)
+
#>                    total.pct total.time self.pct self.time
−
> flatProfile(readProfileData(tmp.log))
+
#> block_exec            100.00      5.94     0.00      0.00
−
              total.pct total.time self.pct self.time
+
#> call_block             100.00       5.94     0.00      0.00
−
desc              100.00      4.82     0.00      0.00
+
#> evaluate              100.00      5.94     0.00      0.00
−
median             73.86       3.56     0.00      0.00
+
#> evaluate_call          100.00       5.94     0.00      0.00
−
median.default     73.86       3.56     0.00      0.00
+
#> in_dir                100.00      5.94    0.00      0.00
−
mean              66.80       3.22     0.00      0.00
+
#> knit                  100.00      5.94    0.00      0.00
−
sort              63.07       3.04     0.00      0.00
+
#> process_file          100.00      5.94    0.00      0.00
−
sort.default      63.07      3.04     0.00      0.00
+
#> process_group          100.00      5.94    0.00      0.00
−
sort.int          63.07       3.04    52.70     2.54
+
#> process_group.block    100.00      5.94    0.00      0.00
−
is.na              14.52       0.70   14.52     0.70
+
#> withCallingHandlers    100.00      5.94    0.00      0.00
−
.Call               9.13       0.44     9.13     0.44
+
#> desc                    99.66       5.92    0.00      0.00
−
sd                 9.13       0.44     0.00      0.00
+
#> eval                    99.66       5.92     0.00      0.00
−
var                 9.13       0.44     0.00      0.00
+
#> handle                  99.66       5.92     0.00      0.00
−
min                7.88       0.38     7.88     0.38
+
#> withVisible            99.66      5.92    0.00      0.00
−
any                 6.64       0.32     6.64     0.32
+
#> median                  80.47      4.78    0.00      0.00
−
max                5.39      0.26     5.39      0.26
+
#> median.default         80.47       4.78    0.00      0.00
−
mean.default       3.73       0.18     3.73     0.18
+
#> mean                    74.07      4.40    0.34      0.02
−
</nowiki>
+
#> sort                    72.73      4.32     0.00      0.00
−
}}
+
#> sort.default            72.73       4.32    0.00     0.00
 +
#> sort.int                72.73       4.32   66.33     3.94
 +
#> .Call                   8.42       0.50     8.42     0.50
 +
#> sd                       8.42       0.50     0.00      0.00
 +
#> var                     8.42       0.50     0.00      0.00
 +
#> is.na                    8.08       0.48     8.08     0.48
 +
#> any                     5.72       0.34     5.72     0.34
 +
#> min                      5.39      0.32     5.39     0.32
 +
#> max                      4.38      0.26    4.38     0.26
 +
#> mean.default             1.01       0.06     1.01     0.06
 +
#> <Anonymous>              0.34      0.02    0.00      0.00
 +
#> formals                  0.34      0.02    0.00      0.00
 +
#> match.arg                0.34      0.02    0.00      0.00
 +
#> sink                    0.34      0.02    0.00      0.00
 +
#> sys.function            0.34      0.02    0.00      0.00
 +
#> sys.parent              0.34      0.02    0.34      0.02
 +
</nowiki>}}
  
 
Функция интересна тем, что предоставляет более компактный вывод при той же информативности, что и функция <code>summaryRprof()</code>.
 
Функция интересна тем, что предоставляет более компактный вывод при той же информативности, что и функция <code>summaryRprof()</code>.
Строка 162: Строка 185:
 
Пакет {{r-package|profr}} предоставляет несколько функций для упрощения процесса профилирования, а также позволяет графически представить результаты профилирования. Результаты работы функции <code>profr</code> представляют собой таблицу, с хронологическим перечислением вызовов. Поэтому при использовании данной функции необходимо использовать однократное выполнение выражения. Вышеприведённый листинг по профилированию работы функции <code>desc()</code> будет выглядеть следующим образом:
 
Пакет {{r-package|profr}} предоставляет несколько функций для упрощения процесса профилирования, а также позволяет графически представить результаты профилирования. Результаты работы функции <code>profr</code> представляют собой таблицу, с хронологическим перечислением вызовов. Поэтому при использовании данной функции необходимо использовать однократное выполнение выражения. Вышеприведённый листинг по профилированию работы функции <code>desc()</code> будет выглядеть следующим образом:
  
−
{{r-code|code=
+
{{r-code|code=<nowiki>prof <- profr(desc(x))
−
<nowiki>> library(profr)
+
print(prof)
−
> prof <- profr(desc(x))
+
#>    level g_id t_id              f start  end n leaf time    source
−
> print(prof)
+
#> 23     1   1    1          desc    0 0.04 1 FALSE 0.04 .GlobalEnv
−
Read 3 items
+
#> 24     2   1    1        median    0 0.04 1 FALSE 0.04     stats
−
                f level time start  end  leaf source
+
#> 25    3    1    1 median.default    0 0.04 1 FALSE 0.04     stats
−
8            desc     1 0.04  0.00 0.04 FALSE   <NA>
+
#> 26    4    1    1           mean    0 0.04 1 FALSE 0.04       base
−
9          median    2 0.02  0.00 0.02 FALSE  stats
+
#> 27    5    1    1           sort    0 0.04 1 FALSE 0.04      base
−
10            sd     2 0.02  0.02 0.04 FALSE  stats
+
#> 28    6    1    1   sort.default    0 0.04 1 FALSE 0.04      base
−
11 median.default    3 0.02  0.00 0.02 FALSE stats
+
#> 29    7    1    1       sort.int    0 0.04 1 TRUE 0.04      base
−
12            var    3 0.02  0.02 0.04 FALSE  stats
+
</nowiki>}}
−
13           mean    4 0.02  0.00 0.02 FALSE   base
+
−
14          .Call    4 0.02  0.02 0.04 TRUE  base
+
−
15           sort    5 0.02  0.00 0.02 FALSE  base
+
−
16   sort.default    6 0.02  0.00 0.02 FALSE  base
+
−
17       sort.int    7 0.02 0.00 0.02  TRUE  base
+
−
</nowiki>
+
−
}}
+
  
 
Содержание столбцов:
 
Содержание столбцов:
Строка 192: Строка 208:
 
Графическое представление результатов профилирования осуществляется с помощью стандартной функции <code>plot()</code> или <code>ggplot()</code>:
 
Графическое представление результатов профилирования осуществляется с помощью стандартной функции <code>plot()</code> или <code>ggplot()</code>:
  
−
{{r-code|code=
+
{{r-code|code=<nowiki>ggplot(prof)
−
<nowiki>> ggplot(prof)
+
</nowiki>}}
−
</nowiki>
+
−
}}
+
  
−
[[Файл:Profr-ggplot-desc.png|600px|center]]
+
[[Файл:Profr-ggplot-desc.svg|600px|center]]
  
 
== Функция <code>proftable</code> ==
 
== Функция <code>proftable</code> ==
  
−
Рассмотрим ещё один способ представления результатов профилирования --- функция <code>proftable()</code>, написанная Noam Ross. Исходный код данной функции доступен под лицензией GNU GPL v2 и размещён в открытом доступе на [https://github.com/noamross/noamtools/blob/master/R/proftable.R github].
+
Рассмотрим ещё один способ представления результатов профилирования - функция <code>proftable()</code>, написанная Noam Ross. Исходный код данной функции доступен под лицензией GNU GPL v2 и размещён в открытом доступе на [https://github.com/noamross/noamtools/blob/master/R/proftable.R github].
  
 
Мы переработали данную функцию, удалив зависимость от пакета {{r-package|plyr}} и существенно ускорив её. Код модифицированного варианта доступен в [http://git.psylab.info/r-scripts/src/master/proftable.R git-репозитории]. Импортировать данный скрипт можно с помощью функции <code>source()</code>:
 
Мы переработали данную функцию, удалив зависимость от пакета {{r-package|plyr}} и существенно ускорив её. Код модифицированного варианта доступен в [http://git.psylab.info/r-scripts/src/master/proftable.R git-репозитории]. Импортировать данный скрипт можно с помощью функции <code>source()</code>:
  
−
{{r-code|code=<nowiki>> source("http://git.psylab.info/r-scripts/raw/master/proftable.R")</nowiki>}}
+
{{r-code|code=<nowiki>source("http://git.psylab.info/r-scripts/raw/master/proftable.R")
 +
</nowiki>}}
  
−
Для корректной работы функции <code>proftable()</code> необходимо провести профилирование с включённой опцией <code>line.profiling</code>. Для удобства последующего анализа результатов можно сохранить функцию и её вызов в файл скрипта и вызывать его с помощью функции <code>source()</code>. Скрипт для профилирования имеет следующее содержимое:
+
Данная функция работает с лог-файлом, полученным в результате профилирования и используется как дополнение к функции <code>summaryRprof()</code>.
  
−
{{file|lang=r|subtitle=/tmp/script.R|code=
+
Для более наглядного представления результатов профилирование необходимо провести с включённой опцией <code>line.profiling</code>. Для удобства последующего анализа результатов можно сохранить функцию и её вызов в файл скрипта и вызывать его с помощью функции <code>source()</code>. В нашем примере скрипт для профилирования имеет следующее содержимое:
−
<nowiki>desc <- function(x) {
+
 
 +
{{file|lang=r|filename=/tmp/script.R|code=<nowiki>desc <- function(x) {
 
     n <- length(x)
 
     n <- length(x)
 
     mean <- mean(x)
 
     mean <- mean(x)
Строка 221: Строка 237:
  
 
for (i in seq_len(100)) desc(x)
 
for (i in seq_len(100)) desc(x)
−
</nowiki>
+
</nowiki>}}
−
}}
+
 
 +
Данный файл можно сформировать прямо из консоли R:
 +
 
 +
{{r-code|code=<nowiki>script <- paste(tempdir(), "script.R", sep = "/")
 +
dump("desc", file = script)
 +
write("for (i in seq_len(100)) desc(x)", file = script, append = TRUE)
 +
</nowiki>}}
  
 
Процедура профилирования осуществляется описанным выше способом:
 
Процедура профилирования осуществляется описанным выше способом:
  
−
{{r-code|code=
+
{{r-code|code=<nowiki>Rprof(tmp.log, line.profiling = TRUE)
−
<nowiki>> Rprof(tmp.log, line.profiling = TRUE)
+
source(script)
−
> source("/tmp/script.R")
+
Rprof(NULL)
−
> Rprof(NULL)
+
</nowiki>}}
−
</nowiki>
+
−
}}
+
  
 
Результаты работы функции <code>proftable()</code> представлены ниже.
 
Результаты работы функции <code>proftable()</code> представлены ниже.
  
−
{{r-code|code=
+
{{r-code|code=<nowiki>proftable(tmp.log)
−
<nowiki>> proftable(tmp.log)
+
#> Calls:
−
  PctTime Call                                                                        
+
#> RealTime PctTime Call                                                                  
−
  54.464 1#4 > median > median.default > mean > sort > sort.default > sort.int         
+
#> 3.94    65.667 median > median.default > mean > sort > sort.default > sort.int         
−
  10.268 1#5 > sd > var > .Call                                                       
+
#> 0.68    11.333 sd > var > .Call                                                       
−
  7.143  1#7 > max                                                                   
+
#> 0.30      5.000 median > median.default > is.na                                         
−
  5.804 1#4 > median > median.default > is.na                                         
+
#>  0.28      4.667 min                                                                   
−
  5.357 1#4 > median > median.default > mean > sort > sort.default > sort.int > is.na
+
#>  0.24      4.000  max                                                                   
−
  5.357 1#6 > min                                                                   
+
#> 0.22      3.667  median > median.default > mean > sort > sort.default > sort.int > is.na
−
  4.464 1#3 > mean > mean.default                                                     
+
#>  0.12      2.000 median > median.default > mean > sort > sort.default > sort.int > any  
−
  3.571  1#4 > median > median.default > any                                           
+
#> 0.10      1.667  mean > mean.default                                                     
−
  3.125 1#4 > median > median.default > mean > sort > sort.default > sort.int > any 
+
#> 0.08      1.333  median > median.default > any                                           
−
  0.446  1#4 > median                                                               
+
#>  0.02      0.333 median > median.default > mean                                        
−
 
+
#>  
−
Files:
+
#> Files: None
−
/tmp/RtmpAvhCfO/file23b65745e7ba.R
+
#>
−
 
+
#> Parent Call: knit > process_file > withCallingHandlers > process_group > process_group.block > call_block > block_exec > in_dir > evaluate > evaluate_call > handle > withCallingHandlers > withVisible > eval > eval > source > withVisible > eval > eval > desc
−
Parent Call: source > withVisible > eval > eval > 1#11 > desc
+
#>  
−
 
+
#> Total Time: 6 seconds
−
Total Time: 4.48 seconds
+
#>
−
Percent of run time represented: 100%
+
#> Percent of run time represented: 99.7%
−
</nowiki>
+
</nowiki>}}
−
}}
+
  
 
Разберём вывод функции <code>proftable()</code>. В первом столбце отображается время выполнения того или иного вызова, во втором --- название вызываемой функции. Далее по цепочке приведена иерархия вызовов. Весь вывод отсортирован по времени выполнения вызовов по убыванию. Вывод наглядно демонстрирует наиболее медленные вызовы вплоть до самого низкого уровня иерархии.
 
Разберём вывод функции <code>proftable()</code>. В первом столбце отображается время выполнения того или иного вызова, во втором --- название вызываемой функции. Далее по цепочке приведена иерархия вызовов. Весь вывод отсортирован по времени выполнения вызовов по убыванию. Вывод наглядно демонстрирует наиболее медленные вызовы вплоть до самого низкого уровня иерархии.
Строка 269: Строка 288:
 
Иногда, чтобы выяснить какой функции принадлежит тот или иной вызов, приходится анализировать содержимое функций. Чтобы увидеть содержимое функции, можно воспользоваться функцией <code>getAnywhere()</code>. Например:
 
Иногда, чтобы выяснить какой функции принадлежит тот или иной вызов, приходится анализировать содержимое функций. Чтобы увидеть содержимое функции, можно воспользоваться функцией <code>getAnywhere()</code>. Например:
  
−
{{r-code|code=
+
{{r-code|code=<nowiki>getAnywhere(median.default)
−
<nowiki>getAnywhere(median.default)
+
#> A single object matching 'median.default' was found
−
A single object matching ‘median.default’ was found
+
#> It was found in the following places
−
It was found in the following places
+
#>   package:stats
−
   package:stats
+
#>   registered S3 method for median from namespace stats
−
   registered S3 method for median from namespace stats
+
#>   namespace:stats
−
   namespace:stats
+
#> with value
−
with value
+
#>
−
 
+
#> function (x, na.rm = FALSE)  
−
function (x, na.rm = FALSE)  
+
#> {
−
{
+
#>     if (is.factor(x) || is.data.frame(x))  
−
     if (is.factor(x) || is.data.frame(x))  
+
#>         stop("need numeric data")
−
         stop("need numeric data")
+
#>     if (length(names(x)))  
−
     if (length(names(x)))  
+
#>         names(x) <- NULL
−
         names(x) <- NULL
+
#>     if (na.rm)  
−
     if (na.rm)  
+
#>         x <- x[!is.na(x)]
−
         x <- x[!is.na(x)]
+
#>     else if (any(is.na(x)))  
−
     else if (any(is.na(x)))  
+
#>         return(x[FALSE][NA])
−
         return(x[FALSE][NA])
+
#>     n <- length(x)
−
     n <- length(x)
+
#>     if (n == 0L)  
−
     if (n == 0L)  
+
#>         return(x[FALSE][NA])
−
         return(x[FALSE][NA])
+
#>     half <- (n + 1L)%/%2L
−
     half <- (n + 1L)%/%2L
+
#>     if (n%%2L == 1L)  
−
     if (n%%2L == 1L)  
+
#>         sort(x, partial = half)[half]
−
         sort(x, partial = half)[half]
+
#>     else mean(sort(x, partial = half + 0L:1L)[half + 0L:1L])
−
     else mean(sort(x, partial = half + 0L:1L)[half + 0L:1L])
+
#> }
−
}
+
#> <bytecode: 0x37bf0b8>
−
<bytecode: 0x3c8f828>
+
#> <environment: namespace:stats>
−
<environment: namespace:stats>
+
</nowiki>}}
−
</nowiki>
+
−
}}
+
  
 
Если искомая функция принадлежит какому-то пакету, то этот пакет должен быть предварительно загружен.
 
Если искомая функция принадлежит какому-то пакету, то этот пакет должен быть предварительно загружен.
Строка 305: Строка 322:
 
С учётом выявленных «узких» мест нашей функции и проанализировав исходный код функций, мы можем оптимизировать нашу исходную функцию для достижения максимальной производительности. Наш вариант оптимизированной функции будет выглядеть следюущим образом:
 
С учётом выявленных «узких» мест нашей функции и проанализировав исходный код функций, мы можем оптимизировать нашу исходную функцию для достижения максимальной производительности. Наш вариант оптимизированной функции будет выглядеть следюущим образом:
  
−
{{r-code|code=
+
{{r-code|code=<nowiki>desc <- function(x) {
−
<nowiki>desc <- function(x) {
+
 
     n <- length(x)
 
     n <- length(x)
 
     mean <- sum(x) / n
 
     mean <- sum(x) / n
Строка 319: Строка 335:
 
     return(c(n, mean, median, sd, min, max))
 
     return(c(n, mean, median, sd, min, max))
 
}
 
}
−
</nowiki>
+
</nowiki>}}
−
}}
+
  
 
Вместо функций <code>median()</code> и <code>sd()</code> мы использовали общеизвестные формулы. А для расчёта медианы была взята часть оригинальной функции <code>median.default</code>, в которой вызов функций <code>sort()</code> был заменён на более быстрый вызов <code>.internal(psort)</code>.
 
Вместо функций <code>median()</code> и <code>sd()</code> мы использовали общеизвестные формулы. А для расчёта медианы была взята часть оригинальной функции <code>median.default</code>, в которой вызов функций <code>sort()</code> был заменён на более быстрый вызов <code>.internal(psort)</code>.

Текущая версия на 20:18, 10 июня 2014



Creative Commons
указание авторства 		Материал «R:Профилирование кода», созданный автором Артём Клевцов, публикуется на условиях лицензии Creative Commons «Attribution» («Атрибуция») 4.0 Всемирная.
Вы можете свободно:
  • делиться произведением – копировать, распространять и передавать данное произведение.
  • создавать производные – переделывать данное произведение.
При соблюдении следующих условий:
  • указание авторства - Вы должны указывать авторство (источник) данного произведения в виде, установленном автором или лицензиаром (но ни в коем случае не таким образом, который наводит на мысль, что автор поддерживает вас или ваше использование данного произведения).


Информация
 Перед использованием функций из пакетов их необходимо предварительно установить и загрузить:
КодR

<syntaxhighlight lang="r">> install.packages(pkgs = "pkgname") > library(package = "pkgname")</syntaxhighlight>

Пакет base

Описанные выше функции system.time(), benchmark(), microbenchmark() позволяют оценить общее время выполнения выражения и нивелировать возможные вариации за счет множества попыток, однако для более полной оценки и определения стратегии оптимизации кода необходимо также выявлять и «узкие» места в выполняемом коде. К подобным «узким» местам можно отнести те вызовы, которые занимают наибольшее количество времени или расходуют больше всего памяти (при профилирования расхода памяти). Существуют специальные пакеты, предназначенные для организации профилирования или для более наглядной демонстрации результатов, однако далее пойдет речь о функции Rprof() из пакета base.

Принцип работы функции Rprof() таков: с заданным интервалом (аргумент interval) делаются «снимки» вызовов и записываются в файл. Следует помнить о том, что Rprof() делает «снимки» каждые 0.02 секунды (значение по умолчанию), поэтому если выражение выполняется быстрее, то Rprof() не сможет его отследить. В таком случае периодичность «снимков» можно задать вручную с помощью аргумента interval. Также можно увеличить объём данных, чтобы код выполнялся дольше.

Ещё одной специфической особенностью профилирования является то, что при профилирования записываются абсолютно все вызовы. Например, если вы используется функцию replicate() для организации повторного выполнения выражения, то вызовы replicate() также будут записаны в лог, что может затруднить его анализ. Аналогичная ситуация будет происходить при вызове скрипта через функцию source()

Обратим внимание, что при профилировании мы можем использовать многократное выполнение анализируемой функции для сбора более надёжной статистики вызовов.

В качестве примера ниже представлены шаги процесса профилирования функции, которая рассчитывает первичные описательные статистики (среднее, медиану, стандартное отклонение, минимум и максимум) по сгенерированным [math]10^6[/math] нормально распределённым значениям.

КодR

<syntaxhighlight lang="r">x <- rnorm(10^6) </syntaxhighlight>

Объявим данную функцию:

КодR

<syntaxhighlight lang="r">desc <- function(x) { n <- length(x) mean <- mean(x) median <- median(x) sd <- sd(x) min <- min(x) max <- max(x) return(c(n, mean, median, sd, min, max)) } </syntaxhighlight>

Шаг 1. Создание временного файла для записи лога профилирования (необязательно):

КодR

<syntaxhighlight lang="r">tmp.log <- tempfile(pattern = "rprof-", fileext = ".log") </syntaxhighlight>

Посмотреть путь и имя временного файла лога можно, введя имя переменной tmp.log:

КодR

<syntaxhighlight lang="r">tmp.log #> [1] "/tmp/Rtmp1kJ8SI/rprof-44673946768c.log" </syntaxhighlight>

Шаг 2. Собственно процедура профилирования:

КодR

<syntaxhighlight lang="r"># Включаем профилирование Rprof(tmp.log) # Выполняем код for (i in seq_len(100)) invisible(desc(x)) # отключаем профилирование Rprof(NULL) </syntaxhighlight>

Шаг 3. Вывод результатов:

КодR

<syntaxhighlight lang="r">summaryRprof(tmp.log) </syntaxhighlight>

Шаг 4. Удаляем временный файл:

КодR

<syntaxhighlight lang="r">unlink(tmp.log) </syntaxhighlight>

Рассмотрим результаты профилирования функции desc():

КодR

<syntaxhighlight lang="r">summaryRprof(tmp.log) #> $by.self #> self.time self.pct total.time total.pct #> "sort.int" 3.94 66.33 4.32 72.73 #> ".Call" 0.50 8.42 0.50 8.42 #> "is.na" 0.48 8.08 0.48 8.08 #> "any" 0.34 5.72 0.34 5.72 #> "min" 0.32 5.39 0.32 5.39 #> "max" 0.26 4.38 0.26 4.38 #> "mean.default" 0.06 1.01 0.06 1.01 #> "mean" 0.02 0.34 4.40 74.07 #> "sys.parent" 0.02 0.34 0.02 0.34 #> #> $by.total #> total.time total.pct self.time self.pct #> "block_exec" 5.94 100.00 0.00 0.00 #> "call_block" 5.94 100.00 0.00 0.00 #> "evaluate" 5.94 100.00 0.00 0.00 #> "evaluate_call" 5.94 100.00 0.00 0.00 #> "in_dir" 5.94 100.00 0.00 0.00 #> "knit" 5.94 100.00 0.00 0.00 #> "process_file" 5.94 100.00 0.00 0.00 #> "process_group" 5.94 100.00 0.00 0.00 #> "process_group.block" 5.94 100.00 0.00 0.00 #> "withCallingHandlers" 5.94 100.00 0.00 0.00 #> "desc" 5.92 99.66 0.00 0.00 #> "eval" 5.92 99.66 0.00 0.00 #> "handle" 5.92 99.66 0.00 0.00 #> "withVisible" 5.92 99.66 0.00 0.00 #> "median" 4.78 80.47 0.00 0.00 #> "median.default" 4.78 80.47 0.00 0.00 #> "mean" 4.40 74.07 0.02 0.34 #> "sort.int" 4.32 72.73 3.94 66.33 #> "sort" 4.32 72.73 0.00 0.00 #> "sort.default" 4.32 72.73 0.00 0.00 #> ".Call" 0.50 8.42 0.50 8.42 #> "sd" 0.50 8.42 0.00 0.00 #> "var" 0.50 8.42 0.00 0.00 #> "is.na" 0.48 8.08 0.48 8.08 #> "any" 0.34 5.72 0.34 5.72 #> "min" 0.32 5.39 0.32 5.39 #> "max" 0.26 4.38 0.26 4.38 #> "mean.default" 0.06 1.01 0.06 1.01 #> "sys.parent" 0.02 0.34 0.02 0.34 #> "<Anonymous>" 0.02 0.34 0.00 0.00 #> "formals" 0.02 0.34 0.00 0.00 #> "match.arg" 0.02 0.34 0.00 0.00 #> "sink" 0.02 0.34 0.00 0.00 #> "sys.function" 0.02 0.34 0.00 0.00 #> #> $sample.interval #> [1] 0.02 #> #> $sampling.time #> [1] 5.94 </syntaxhighlight>

Результатом подобных операций является 2 таблицы, отсортированные по разным основаниям: по времени выполнения функции (self.time) и общему времени выполнения функции (total.time). В столбцах представлены абсолютные и относительные (в процентах) показатели времени выполнения.

При профилировании скриптов включение опции line.profiling проставляет номера строк в которых производился вызов, что позволяет проанализировать производительность всего кода:

КодR

<syntaxhighlight lang="r">Rprof(tmp.log, line.profiling = TRUE) source("/path/scritpt.R") Rprof(NULL) summaryRprof(tmp.log) unlink(tmp.log) </syntaxhighlight>

Пакет proftools

Также может оказаться полезной функция flatProfile() из пакета proftools. Данная функция выводит таблицу, сходную с таблицей «by.total» возвращаемую функцией summaryRprof(), в одну и сортирует их по общему времени выполнения в процентах или по времени выполнения функции в процентах, если указать byTotal = FALSE:

КодR

<syntaxhighlight lang="r">flatProfile(readProfileData(tmp.log)) #> total.pct total.time self.pct self.time #> block_exec 100.00 5.94 0.00 0.00 #> call_block 100.00 5.94 0.00 0.00 #> evaluate 100.00 5.94 0.00 0.00 #> evaluate_call 100.00 5.94 0.00 0.00 #> in_dir 100.00 5.94 0.00 0.00 #> knit 100.00 5.94 0.00 0.00 #> process_file 100.00 5.94 0.00 0.00 #> process_group 100.00 5.94 0.00 0.00 #> process_group.block 100.00 5.94 0.00 0.00 #> withCallingHandlers 100.00 5.94 0.00 0.00 #> desc 99.66 5.92 0.00 0.00 #> eval 99.66 5.92 0.00 0.00 #> handle 99.66 5.92 0.00 0.00 #> withVisible 99.66 5.92 0.00 0.00 #> median 80.47 4.78 0.00 0.00 #> median.default 80.47 4.78 0.00 0.00 #> mean 74.07 4.40 0.34 0.02 #> sort 72.73 4.32 0.00 0.00 #> sort.default 72.73 4.32 0.00 0.00 #> sort.int 72.73 4.32 66.33 3.94 #> .Call 8.42 0.50 8.42 0.50 #> sd 8.42 0.50 0.00 0.00 #> var 8.42 0.50 0.00 0.00 #> is.na 8.08 0.48 8.08 0.48 #> any 5.72 0.34 5.72 0.34 #> min 5.39 0.32 5.39 0.32 #> max 4.38 0.26 4.38 0.26 #> mean.default 1.01 0.06 1.01 0.06 #> <Anonymous> 0.34 0.02 0.00 0.00 #> formals 0.34 0.02 0.00 0.00 #> match.arg 0.34 0.02 0.00 0.00 #> sink 0.34 0.02 0.00 0.00 #> sys.function 0.34 0.02 0.00 0.00 #> sys.parent 0.34 0.02 0.34 0.02 </syntaxhighlight>

Функция интересна тем, что предоставляет более компактный вывод при той же информативности, что и функция summaryRprof().

Пакет <profr

Пакет profr предоставляет несколько функций для упрощения процесса профилирования, а также позволяет графически представить результаты профилирования. Результаты работы функции profr представляют собой таблицу, с хронологическим перечислением вызовов. Поэтому при использовании данной функции необходимо использовать однократное выполнение выражения. Вышеприведённый листинг по профилированию работы функции desc() будет выглядеть следующим образом:

КодR

<syntaxhighlight lang="r">prof <- profr(desc(x)) print(prof) #> level g_id t_id f start end n leaf time source #> 23 1 1 1 desc 0 0.04 1 FALSE 0.04 .GlobalEnv #> 24 2 1 1 median 0 0.04 1 FALSE 0.04 stats #> 25 3 1 1 median.default 0 0.04 1 FALSE 0.04 stats #> 26 4 1 1 mean 0 0.04 1 FALSE 0.04 base #> 27 5 1 1 sort 0 0.04 1 FALSE 0.04 base #> 28 6 1 1 sort.default 0 0.04 1 FALSE 0.04 base #> 29 7 1 1 sort.int 0 0.04 1 TRUE 0.04 base </syntaxhighlight>

Содержание столбцов:

  • «f» --- название функции;
  • «level» --- уровень в иерархии вызовов;
  • «time» --- общее время выполнения функции;
  • «start» --- время начала выполнения функции;
  • «end» --- время окончания выполнения функции;
  • «leaf» --- TRUE, если функция вызывается другими функциями;
  • «source» --- название пакеты, содержащего данную функцию.

Графическое представление результатов профилирования осуществляется с помощью стандартной функции plot() или ggplot():

КодR

<syntaxhighlight lang="r">ggplot(prof) </syntaxhighlight>

Profr-ggplot-desc.svg

Функция proftable

Рассмотрим ещё один способ представления результатов профилирования - функция proftable(), написанная Noam Ross. Исходный код данной функции доступен под лицензией GNU GPL v2 и размещён в открытом доступе на github.

Мы переработали данную функцию, удалив зависимость от пакета plyr и существенно ускорив её. Код модифицированного варианта доступен в git-репозитории. Импортировать данный скрипт можно с помощью функции source():

КодR

<syntaxhighlight lang="r">source("http://git.psylab.info/r-scripts/raw/master/proftable.R") </syntaxhighlight>

Данная функция работает с лог-файлом, полученным в результате профилирования и используется как дополнение к функции summaryRprof().

Для более наглядного представления результатов профилирование необходимо провести с включённой опцией line.profiling. Для удобства последующего анализа результатов можно сохранить функцию и её вызов в файл скрипта и вызывать его с помощью функции source(). В нашем примере скрипт для профилирования имеет следующее содержимое:

Файл/tmp/script.R

<syntaxhighlight lang="r" enclose="pre">desc <- function(x) { n <- length(x) mean <- mean(x) median <- median(x) sd <- sd(x) min <- min(x) max <- max(x) return(c(n, mean, median, sd, min, max)) } for (i in seq_len(100)) desc(x) </syntaxhighlight>

Данный файл можно сформировать прямо из консоли R:

КодR

<syntaxhighlight lang="r">script <- paste(tempdir(), "script.R", sep = "/") dump("desc", file = script) write("for (i in seq_len(100)) desc(x)", file = script, append = TRUE) </syntaxhighlight>

Процедура профилирования осуществляется описанным выше способом:

КодR

<syntaxhighlight lang="r">Rprof(tmp.log, line.profiling = TRUE) source(script) Rprof(NULL) </syntaxhighlight>

Результаты работы функции proftable() представлены ниже.

КодR

<syntaxhighlight lang="r">proftable(tmp.log) #> Calls: #> RealTime PctTime Call #> 3.94 65.667 median > median.default > mean > sort > sort.default > sort.int #> 0.68 11.333 sd > var > .Call #> 0.30 5.000 median > median.default > is.na #> 0.28 4.667 min #> 0.24 4.000 max #> 0.22 3.667 median > median.default > mean > sort > sort.default > sort.int > is.na #> 0.12 2.000 median > median.default > mean > sort > sort.default > sort.int > any #> 0.10 1.667 mean > mean.default #> 0.08 1.333 median > median.default > any #> 0.02 0.333 median > median.default > mean #> #> Files: None #> #> Parent Call: knit > process_file > withCallingHandlers > process_group > process_group.block > call_block > block_exec > in_dir > evaluate > evaluate_call > handle > withCallingHandlers > withVisible > eval > eval > source > withVisible > eval > eval > desc #> #> Total Time: 6 seconds #> #> Percent of run time represented: 99.7% </syntaxhighlight>

Разберём вывод функции proftable(). В первом столбце отображается время выполнения того или иного вызова, во втором --- название вызываемой функции. Далее по цепочке приведена иерархия вызовов. Весь вывод отсортирован по времени выполнения вызовов по убыванию. Вывод наглядно демонстрирует наиболее медленные вызовы вплоть до самого низкого уровня иерархии.

Обратите внимание, что функция proftable() имеет второй аргумент --- lines, который отвечает за количество строк в выводе (значение по умолчанию - 10).

Выводы

Из примера выше мы можем сделать вывод, что наиболее медленной функцией из состава функции desc() является функция median(), которая через некоторую последовательность вызовов вызывает функцию sort.int(). Именно функция sort.int() является наиболее «узким» местом всех расчётов.

Иногда, чтобы выяснить какой функции принадлежит тот или иной вызов, приходится анализировать содержимое функций. Чтобы увидеть содержимое функции, можно воспользоваться функцией getAnywhere(). Например:

КодR

<syntaxhighlight lang="r">getAnywhere(median.default) #> A single object matching 'median.default' was found #> It was found in the following places #> package:stats #> registered S3 method for median from namespace stats #> namespace:stats #> with value #> #> function (x, na.rm = FALSE) #> { #> if (is.factor(x) || is.data.frame(x)) #> stop("need numeric data") #> if (length(names(x))) #> names(x) <- NULL #> if (na.rm) #> x <- x[!is.na(x)] #> else if (any(is.na(x))) #> return(x[FALSE][NA]) #> n <- length(x) #> if (n == 0L) #> return(x[FALSE][NA]) #> half <- (n + 1L)%/%2L #> if (n%%2L == 1L) #> sort(x, partial = half)[half] #> else mean(sort(x, partial = half + 0L:1L)[half + 0L:1L]) #> } #> <bytecode: 0x37bf0b8> #> <environment: namespace:stats> </syntaxhighlight>

Если искомая функция принадлежит какому-то пакету, то этот пакет должен быть предварительно загружен.

С учётом выявленных «узких» мест нашей функции и проанализировав исходный код функций, мы можем оптимизировать нашу исходную функцию для достижения максимальной производительности. Наш вариант оптимизированной функции будет выглядеть следюущим образом:

КодR

<syntaxhighlight lang="r">desc <- function(x) { n <- length(x) mean <- sum(x) / n sd <- sqrt(sum((x - mean)^2) / (n - 1)) min <- min(x) max <- max(x) half <- (n + 1L) %/% 2L if (n %% 2L == 1L) median <- .Internal(psort(x, half))[half] else median <- sum(.Internal(psort(x, c(half, half + 1)))[c(half, half + 1)]) / 2L return(c(n, mean, median, sd, min, max)) } </syntaxhighlight>

Вместо функций median() и sd() мы использовали общеизвестные формулы. А для расчёта медианы была взята часть оригинальной функции median.default, в которой вызов функций sort() был заменён на более быстрый вызов .internal(psort).

Примечания


Ссылки

Источник — «https://psylab.info/index.php?title=R:Профилирование_кода&oldid=9264»