다음은 주어진 벡터에 1을 더하는 비효율적인 함수에 대해 코드 프로파일링을 수행하는 예를 보여준다. 코드에서 seq_along( )은 인자로 주어진 벡터의 길이만큼 1, 2, 3, …, N으로 구성된 숫자 벡터를 생성하는 함수다.

> add_one <- function(val) {
+   return(val + 1)
+ }

> add_one_to_vec <- function(x) {
+   for (i in seq_along(x)) {
+     x[i] <- add_one(x[i])
+   }
+   return(x)
+ }

> Rprof("add_one.out")
> x <- add_one_to_vec(1:1000000)
> head(x)
[1] 2 3 4 5 6 7
> Rprof(NULL)

코드를 실행하면 add_one.out이라는 파일이 생성된다. 결과를 분석하려면 Rprof( )가 생성한 파일을 summaryRprof( )에 넘겨주면 된다.

> summaryRprof("add_one.out")
$by.self
                  self.time self.pct total.time total.pct
"add_one"              3.08    50.49       3.32     54.43
"add_one_to_vec"       2.78    45.57       6.10    100.00
"+"                    0.24     3.93       0.24      3.93

$by.total
                 total.time total.pct self.time self.pct
"add_one_to_vec"       6.10    100.00      2.78    45.57
"add_one"              3.32     54.43      3.08    50.49
"+"                    0.24      3.93       0.24     3.93

$sample.interval
[1] 0.02

$sampling.time
[1] 6.1

summaryRprof( )의 분석 결과는 크게 by.self와 by.total 두 섹션으로 나뉘는데, 이 두 섹션에 들어 있는 내용은 동일하다. 다만 by.self는 self.time으로 정렬된 표이고, by.total은 total.time으로 정렬된 표다. 따라서 설명의 편의를 위해 여기서는 by.self를 기준으로 살펴보기로 하자.

> summaryRprof("add_one.out")$by.self
                 self.time self.pct total.time total.pct
"add_one"             3.08    50.49       3.32     54.43
"add_one_to_vec"      2.78    45.57       6.10    100.00
"+"                   0.24     3.93       0.24      3.93

표에서 self.time은 각 함수가 수행하는 데 걸린 시간이다. add_one은 해당 함수 내 코드를 수행하는 데 3.08초가 소요되었으며, add_one_to_vec은 함수 내 코드를 수행하는 데 2.78초가 소요되었다. 코드 전체 수행 시간 대비 각 함수의 self.time 시간의 비율은 self.pct를 통해 알 수 있다.

total.time은 각 함수 내 코드를 수행하는 데 걸린 시간과 해당 함수가 호출한 함수를 수행하는 데 걸린 시간의 합이다. 예를 들어, + 연산은 self.time이 0.24초였다. + 연산자 자체는 단독으로 수행되므로 total.time도 0.24초다. 반면 add_one 함수는 해당 함수 내에서 val + 1 명령을 수행하기 위해 +를 호출한다. 따라서 add_one의 total.time은 자신의 self.time 3.08초에 +의 self.time 0.24초를 더한 3.32초다. 마찬가지로 add_one_to_vec은 해당 함수 내 코드를 수행하는 데 2.78초가 걸리고 여기에 add_one을 호출하므로 add_one의 total.time인 3.32초가 추가로 걸린다. 따라서 add_one_to_vec의 total.time은 2.78 + 3.32 = 6.10초다.

이처럼 summaryRprof( )의 결과는 어떤 함수가 수행하는 데 얼마나 시간이 소모되는지를 좀 더 쉽고 분석적으로 나열해주므로, 어떤 함수에서 가장 긴 시간이 소모되는지를 판단할 수 있다. 만약 R 코드의 성능이 만족스럽지 못하다면 Rprof( )를 사용해 소모 시간과 그 비율을 판단하고 가장 긴 시간이 걸리는 항목부터 개선해나감으로써 더 과학적인 성능 개선을 이룰 수 있다.

Rprof( )에는 여기에서 설명하지 않은 메모리 프로파일링 등의 다양한 옵션이 있으므로 코드 성능 평가 시 help(Rprof)를 살펴보기 바란다.