Measuring execution time with system.time()

The first profiling tool we will learn about is system.time(). It is a very useful tool that we can use to measure the execution time of any R expression.

Say we want to find out how long it takes to generate 100 million uniform random variables. Take a look at the following statement and the output when it is run in the R console:

system.time(runif(1e8))
##  user  system elapsed 
## 2.969   0.166   3.138

The runif(1e8) expression generates 100 million random values between 0 and 1. In order to measure how long it takes to run this command, we simply pass this expression to system.time().

The output contains three elements, all measured in seconds:

Most of the time, we are interested in the total elapsed time to execute the given expression. When the expression is executed on a single thread (the default for R), the elapsed time is usually very close to the sum of the user time and system time. If that is not the case, either the expression has spent time waiting for resources to be available, or there were many other processes on the system competing for the CPU's time.

This is what happens when we run system.time() a few more times with the same expression:

system.time(runif(1e8))
##  user  system elapsed 
## 2.963   0.160   3.128 
system.time(runif(1e8))
##  user  system elapsed 
## 2.971   0.162   3.136 
system.time(runif(1e8))
##  user  system elapsed 
## 2.944   0.161   3.106

By running system.time() repeatedly, we get slightly different results each time because R's overheads, OS caching mechanisms, other running processes, and many other factors might have a slight impact on the execution time.

Repeating time measurements with rbenchmark

It is sometimes helpful to run the same expression multiple times and get the average execution time, or even the distribution of execution times over multiple runs. The rbenchmark CRAN package lets us do this easily.

First, install and load the rbenchmark package:

install.packages("rbenchmark")
library(rbenchmark)

Next, use benchmark() to run the same random number generation task 10 times, by specifying replications=10:

bench1 <- benchmark(runif(1e8), replications=10)
bench1
##           test replications elapsed relative user.self
## 1 runif(1e+08)           10   32.38        1    29.781
##   sys.self user.child sys.child
## 1    2.565          0         0

The results show the total elapsed system and user time taken to generate 100 million uniform random variables over 10 repetitions. We can find the mean times taken per repetition using within() to divide the time measurements by the number of repetitions:

within(bench1, {
       elapsed.mean <- elapsed/replications
       user.self.mean <- user.self/replications
       sys.self.mean <- sys.self/replications
       })
##           test replications elapsed relative user.self
## 1 runif(1e+08)           10   32.38        1    29.781
##   sys.self user.child sys.child sys.self.mean user.self.mean
## 1    2.565          0         0        0.2565         2.9781
##   elapsed.mean
## 1        3.238

What if we want to know the execution times for each repetition, or the distribution of execution times over the repetitions? We can pass a vector instead of a single number as the replications parameter. For each element of this vector, benchmark() will execute the given expression the specified number of times. So we can get 10 samples of the execution of the random number generation once, as shown in the following code. In addition to the elapsed user and system time, benchmark() returns an additional column, relative, which indicates how each repetition's elapsed time is compared with the fastest one. For example, the first repetition took 1.011 times as long as the fastest repetition (the fourth one), or 1.1 percent longer to run:

benchmark(runif(1e8), replications=rep.int(1, 10))
##            test replications elapsed relative user.self
## 1  runif(1e+08)            1   3.162    1.011     2.971
## 2  runif(1e+08)            1   3.145    1.005     2.951
## 3  runif(1e+08)            1   3.141    1.004     2.949
## 4  runif(1e+08)            1   3.128    1.000     2.937
## 5  runif(1e+08)            1   3.261    1.043     3.021
## 6  runif(1e+08)            1   3.207    1.025     2.993
## 7  runif(1e+08)            1   3.274    1.047     3.035
## 8  runif(1e+08)            1   3.174    1.015     2.966
## 9  runif(1e+08)            1   3.172    1.014     2.970
## 10 runif(1e+08)            1   3.230    1.033     3.004
##    sys.self user.child sys.child
## 1     0.187          0         0
## 2     0.191          0         0
## 3     0.189          0         0
## 4     0.190          0         0
## 5     0.228          0         0
## 6     0.210          0         0
## 7     0.230          0         0
## 8     0.207          0         0
## 9     0.201          0         0
## 10    0.224          0         0

Measuring distribution of execution time with microbenchmark

The CRAN package microbenchmark provides yet another way to measure the execution time of an R expression. Though its microbenchmark() function only measures the elapsed time and not the user time or system time, it gives an idea of how the execution times across repeated runs are distributed. It also automatically corrects for the overheads related to the execution of the timing tests. The microbenchmark() function is very handy to measure short running tasks over many repetitions provided you do not need to measure the user or system times. We will use this tool many times throughout this book.

Install and load the microbenchmark package:

install.packages("microbenchmark")
library(microbenchmark)

Now, run the same random number generation task 10 times using microbenchmark():

microbenchmark(runif(1e8), times=10)
## Unit: seconds
##          expr      min       lq  median       uq      max
##  runif(1e+08) 3.170571 3.193331 3.25089 3.299966 3.314355
##  neval
##     10

The statistics shows the minimum, lower quartile, median, upper quartile, and maximum values of the elapsed time over 10 repetitions. This gives us an idea of the distribution of the elapsed times over different repetitions of the same expression.