Introduction
Taking measurements of execution (run-time) of an R function or code chunk in R is often necessary when profiling the code to determine bottlenecks and to compare different implementations. It can also be useful to ascertain the run-time complexity of package functions. There are several packages for benchmarking R code as well as two built-in Base R functions for measuring time. This lesson will look at the most commonly used options.
Using “Sys.time”
The function Sys.time()
is part of Base R, so no additional packages are required. It returns the current time. Calling the function before and after some code that is to be measured and then calculating the difference in time elapsed provides a simple way to measure the run-time of a chunk of code. This is one of the simplest and most flexible approaches and generally sufficient. The function returns a “difftime” object which must be converted to a numeric type for any further computations.
The example below illustrates that approach. It loads a CSV and counts the number of female customers using a loop.
bt <- Sys.time()
df <- read.csv(file = "customertxndata.csv", header = T)
femCounter <- 0
for (i in 1:nrow(df))
{
if (!is.na(df$Gender[i]) && df$Gender[i] == "Female")
femCounter = femCounter + 1
}
et <- Sys.time()
t.loop <- et - bt
cat("Time elapsed: ", round((t.loop),3), " sec")
Time elapsed: 0.321 sec
The code below also counts the number of female customers but uses which()
instead of a loop in order to measure the time difference between the two approaches.
bt <- Sys.time()
df <- read.csv(file = "customertxndata.csv", header = T)
femCounter <- 0
n <- which(df$Gender == "Female")
femCounter <- length(n)
et <- Sys.time()
t.which <- et - bt
cat("Time elapsed: ", round((t.which),3), " sec")
Time elapsed: 0.111 sec
So, based on profiling the code, a linear search of a data frame with 91200 rows using a loop takes 0.321 seconds while using which()
is 0.21 seconds faster.
Using “system.time”
The function takes system.time()
takes an R expression as an argument and then returns a report on the time spent executing the expression. It reports the time spent running the actual code (user), the time spent calling operating system functions (system), and the total time elapsed which includes any time that the process is blocked.
The code below illustrates the use of this function.
processDF <- function ()
{
df <- read.csv(file = "customertxndata.csv", header = T)
femCounter <- 0
n <- which(df$Gender == "Female")
femCounter <- length(n)
}
system.time(processDF())
user system elapsed
0.103 0.001 0.105
Generally, the most useful reported time is elapsed time as it is the entire time needed to run the expression. Note that the function also uses some time to run, so the time reported here will be a little bit longer than if you measured it using another method – but that is rarely of any practical consequence.
Other Methods
The benchmark package contains functions rbenchmark()
while the package microbenchmark has the function microbenchmark()
which take expressions as parameters and report the run-time of each making code comparisons simpler. The microbenchmark package also contains visualizations for benchmarks built using gplot2.
Summary
The most common and simplest approach to measuring the execution time of an R expression or a code chunk is to use either Sys.time()
or system.time()
.
Errata
None collected yet. Let us know.
LS0tDQp0aXRsZTogIk1lYXN1cmUgUnVuLVRpbWUgUGVyZm9ybWFuY2Ugb2YgUiBDb2RlIg0KcGFyYW1zOg0KICBjYXRlZ29yeTogNg0KICBudW1iZXI6IDEzNA0KICB0aW1lOiA0NQ0KICBsZXZlbDogYmVnaW5uZXINCiAgdGFnczogIlIsZGVidWdnaW5nLHJ1bnRpbWUsdGltZSxTeXMudGltZSx0aWN0b2MscmJlbmNobWFyayINCiAgZGVzY3JpcHRpb246ICJEZW1vbnN0cmF0ZXMgaG93IHRvIG1lYXN1cmUgdGhlIGV4ZWN1dGlvbiB0aW1lIG9mIFINCiAgICAgICAgICAgICAgICBjb2RlIGZvciBwcm9maWxpbmcsIGRlYnVnZ2luZywgYW5kIHBlcmZvcm1hbmNlDQogICAgICAgICAgICAgICAgaW1wcm92ZW1lbmV0LiINCmRhdGU6ICI8c21hbGw+YHIgU3lzLkRhdGUoKWA8L3NtYWxsPiINCmF1dGhvcjogIjxzbWFsbD5NYXJ0aW4gU2NoZWRsYmF1ZXI8L3NtYWxsPiINCmVtYWlsOiAibS5zY2hlZGxiYXVlckBuZXUuZWR1Ig0KYWZmaWxpdGF0aW9uOiAiTm9ydGhlYXN0ZXJuIFVuaXZlcnNpdHkiDQpvdXRwdXQ6IA0KICBib29rZG93bjo6aHRtbF9kb2N1bWVudDI6DQogICAgdG9jOiB0cnVlDQogICAgdG9jX2Zsb2F0OiB0cnVlDQogICAgY29sbGFwc2VkOiBmYWxzZQ0KICAgIG51bWJlcl9zZWN0aW9uczogZmFsc2UNCiAgICBjb2RlX2Rvd25sb2FkOiB0cnVlDQogICAgdGhlbWU6IHNwYWNlbGFiDQogICAgaGlnaGxpZ2h0OiB0YW5nbw0KLS0tDQoNCi0tLQ0KdGl0bGU6ICI8c21hbGw+YHIgcGFyYW1zJGNhdGVnb3J5YC5gciBwYXJhbXMkbnVtYmVyYDwvc21hbGw+PGJyLz48c3BhbiBzdHlsZT0nY29sb3I6ICMyRTQwNTM7IGZvbnQtc2l6ZTogMC45ZW0nPmByIHJtYXJrZG93bjo6bWV0YWRhdGEkdGl0bGVgPC9zcGFuPiINCi0tLQ0KDQpgYGB7ciBjb2RlPXhmdW46OnJlYWRfdXRmOChwYXN0ZTAoaGVyZTo6aGVyZSgpLCcvUi9faW5zZXJ0MkRCLlInKSksIGluY2x1ZGUgPSBGQUxTRX0NCmBgYA0KDQojIyBJbnRyb2R1Y3Rpb24NCg0KVGFraW5nIG1lYXN1cmVtZW50cyBvZiBleGVjdXRpb24gKHJ1bi10aW1lKSBvZiBhbiBSIGZ1bmN0aW9uIG9yIGNvZGUgY2h1bmsgaW4gUiBpcyBvZnRlbiBuZWNlc3Nhcnkgd2hlbiBwcm9maWxpbmcgdGhlIGNvZGUgdG8gZGV0ZXJtaW5lIGJvdHRsZW5lY2tzIGFuZCB0byBjb21wYXJlIGRpZmZlcmVudCBpbXBsZW1lbnRhdGlvbnMuIEl0IGNhbiBhbHNvIGJlIHVzZWZ1bCB0byBhc2NlcnRhaW4gdGhlIHJ1bi10aW1lIGNvbXBsZXhpdHkgb2YgcGFja2FnZSBmdW5jdGlvbnMuIFRoZXJlIGFyZSBzZXZlcmFsIHBhY2thZ2VzIGZvciBiZW5jaG1hcmtpbmcgUiBjb2RlIGFzIHdlbGwgYXMgdHdvIGJ1aWx0LWluIEJhc2UgUiBmdW5jdGlvbnMgZm9yIG1lYXN1cmluZyB0aW1lLiBUaGlzIGxlc3NvbiB3aWxsIGxvb2sgYXQgdGhlIG1vc3QgY29tbW9ubHkgdXNlZCBvcHRpb25zLg0KDQojIyBVc2luZyAiU3lzLnRpbWUiDQoNClRoZSBmdW5jdGlvbiA8Y29kZT5TeXMudGltZSgpPC9jb2RlPiBpcyBwYXJ0IG9mIEJhc2UgUiwgc28gbm8gYWRkaXRpb25hbCBwYWNrYWdlcyBhcmUgcmVxdWlyZWQuIEl0IHJldHVybnMgdGhlIGN1cnJlbnQgdGltZS4gQ2FsbGluZyB0aGUgZnVuY3Rpb24gYmVmb3JlIGFuZCBhZnRlciBzb21lIGNvZGUgdGhhdCBpcyB0byBiZSBtZWFzdXJlZCBhbmQgdGhlbiBjYWxjdWxhdGluZyB0aGUgZGlmZmVyZW5jZSBpbiB0aW1lIGVsYXBzZWQgcHJvdmlkZXMgYSBzaW1wbGUgd2F5IHRvIG1lYXN1cmUgdGhlIHJ1bi10aW1lIG9mIGEgY2h1bmsgb2YgY29kZS4gVGhpcyBpcyBvbmUgb2YgdGhlIHNpbXBsZXN0IGFuZCBtb3N0IGZsZXhpYmxlIGFwcHJvYWNoZXMgYW5kIGdlbmVyYWxseSBzdWZmaWNpZW50LiBUaGUgZnVuY3Rpb24gcmV0dXJucyBhICJkaWZmdGltZSIgb2JqZWN0IHdoaWNoIG11c3QgYmUgY29udmVydGVkIHRvIGEgbnVtZXJpYyB0eXBlIGZvciBhbnkgZnVydGhlciBjb21wdXRhdGlvbnMuDQoNClRoZSBleGFtcGxlIGJlbG93IGlsbHVzdHJhdGVzIHRoYXQgYXBwcm9hY2guIEl0IGxvYWRzIGEgQ1NWIGFuZCBjb3VudHMgdGhlIG51bWJlciBvZiBmZW1hbGUgY3VzdG9tZXJzIHVzaW5nIGEgbG9vcC4NCg0KYGBge3IgdXNpbmdTeXMudGltZTEsIGV2YWw9VCwgZWNobz1ULCBjb21tZW50PSIifQ0KDQpidCA8LSBTeXMudGltZSgpDQoNCmRmIDwtIHJlYWQuY3N2KGZpbGUgPSAiY3VzdG9tZXJ0eG5kYXRhLmNzdiIsIGhlYWRlciA9IFQpDQoNCmZlbUNvdW50ZXIgPC0gMA0KDQpmb3IgKGkgaW4gMTpucm93KGRmKSkNCnsNCiAgaWYgKCFpcy5uYShkZiRHZW5kZXJbaV0pICYmIGRmJEdlbmRlcltpXSA9PSAiRmVtYWxlIikNCiAgICBmZW1Db3VudGVyID0gZmVtQ291bnRlciArIDENCn0NCg0KZXQgPC0gU3lzLnRpbWUoKQ0KDQp0Lmxvb3AgPC0gZXQgLSBidA0KDQpjYXQoIlRpbWUgZWxhcHNlZDogIiwgcm91bmQoKHQubG9vcCksMyksICIgc2VjIikNCmBgYA0KDQpUaGUgY29kZSBiZWxvdyBhbHNvIGNvdW50cyB0aGUgbnVtYmVyIG9mIGZlbWFsZSBjdXN0b21lcnMgYnV0IHVzZXMgPGNvZGU+d2hpY2goKTwvY29kZT4gaW5zdGVhZCBvZiBhIGxvb3AgaW4gb3JkZXIgdG8gbWVhc3VyZSB0aGUgdGltZSBkaWZmZXJlbmNlIGJldHdlZW4gdGhlIHR3byBhcHByb2FjaGVzLg0KDQpgYGB7ciB1c2luZ1N5cy50aW1lMiwgZXZhbD1ULCBlY2hvPVQsIGNvbW1lbnQ9IiJ9DQoNCmJ0IDwtIFN5cy50aW1lKCkNCg0KZGYgPC0gcmVhZC5jc3YoZmlsZSA9ICJjdXN0b21lcnR4bmRhdGEuY3N2IiwgaGVhZGVyID0gVCkNCg0KZmVtQ291bnRlciA8LSAwDQoNCm4gPC0gd2hpY2goZGYkR2VuZGVyID09ICJGZW1hbGUiKQ0KZmVtQ291bnRlciA8LSBsZW5ndGgobikNCg0KZXQgPC0gU3lzLnRpbWUoKQ0KDQp0LndoaWNoIDwtIGV0IC0gYnQNCg0KY2F0KCJUaW1lIGVsYXBzZWQ6ICIsIHJvdW5kKCh0LndoaWNoKSwzKSwgIiBzZWMiKQ0KYGBgDQoNClNvLCBiYXNlZCBvbiBwcm9maWxpbmcgdGhlIGNvZGUsIGEgbGluZWFyIHNlYXJjaCBvZiBhIGRhdGEgZnJhbWUgd2l0aCBgciBucm93KGRmKWAgcm93cyB1c2luZyBhIGxvb3AgdGFrZXMgYHIgcm91bmQodC5sb29wLDMpYCBzZWNvbmRzIHdoaWxlIHVzaW5nIDxjb2RlPndoaWNoKCk8L2NvZGU+IGlzIGByIHJvdW5kKHQubG9vcCAtIHQud2hpY2gsIDMpYCBzZWNvbmRzIGZhc3Rlci4NCg0KIyMgVXNpbmcgInN5c3RlbS50aW1lIg0KDQpUaGUgZnVuY3Rpb24gdGFrZXMgPGNvZGU+c3lzdGVtLnRpbWUoKTwvY29kZT4gdGFrZXMgYW4gUiBleHByZXNzaW9uIGFzIGFuIGFyZ3VtZW50IGFuZCB0aGVuIHJldHVybnMgYSByZXBvcnQgb24gdGhlIHRpbWUgc3BlbnQgZXhlY3V0aW5nIHRoZSBleHByZXNzaW9uLiBJdCByZXBvcnRzIHRoZSB0aW1lIHNwZW50IHJ1bm5pbmcgdGhlIGFjdHVhbCBjb2RlICh1c2VyKSwgdGhlIHRpbWUgc3BlbnQgY2FsbGluZyBvcGVyYXRpbmcgc3lzdGVtIGZ1bmN0aW9ucyAoc3lzdGVtKSwgYW5kIHRoZSB0b3RhbCB0aW1lIGVsYXBzZWQgd2hpY2ggaW5jbHVkZXMgYW55IHRpbWUgdGhhdCB0aGUgcHJvY2VzcyBpcyBibG9ja2VkLg0KDQpUaGUgY29kZSBiZWxvdyBpbGx1c3RyYXRlcyB0aGUgdXNlIG9mIHRoaXMgZnVuY3Rpb24uDQoNCmBgYHtyIHVzaW5nLnN5c3RlbS50aW1lLCBldmFsPVQsIGVjaG89VCwgY29tbWVudD0iIn0NCg0KcHJvY2Vzc0RGIDwtIGZ1bmN0aW9uICgpDQp7DQogIGRmIDwtIHJlYWQuY3N2KGZpbGUgPSAiY3VzdG9tZXJ0eG5kYXRhLmNzdiIsIGhlYWRlciA9IFQpDQogIA0KICBmZW1Db3VudGVyIDwtIDANCiAgDQogIG4gPC0gd2hpY2goZGYkR2VuZGVyID09ICJGZW1hbGUiKQ0KICBmZW1Db3VudGVyIDwtIGxlbmd0aChuKQ0KfQ0KDQpzeXN0ZW0udGltZShwcm9jZXNzREYoKSkNCmBgYA0KDQpHZW5lcmFsbHksIHRoZSBtb3N0IHVzZWZ1bCByZXBvcnRlZCB0aW1lIGlzICplbGFwc2VkKiB0aW1lIGFzIGl0IGlzIHRoZSBlbnRpcmUgdGltZSBuZWVkZWQgdG8gcnVuIHRoZSBleHByZXNzaW9uLiBOb3RlIHRoYXQgdGhlIGZ1bmN0aW9uIGFsc28gdXNlcyBzb21lIHRpbWUgdG8gcnVuLCBzbyB0aGUgdGltZSByZXBvcnRlZCBoZXJlIHdpbGwgYmUgYSBsaXR0bGUgYml0IGxvbmdlciB0aGFuIGlmIHlvdSBtZWFzdXJlZCBpdCB1c2luZyBhbm90aGVyIG1ldGhvZCAtLSBidXQgdGhhdCBpcyByYXJlbHkgb2YgYW55IHByYWN0aWNhbCBjb25zZXF1ZW5jZS4NCg0KIyMgT3RoZXIgTWV0aG9kcw0KDQpUaGUgKipiZW5jaG1hcmsqKiBwYWNrYWdlIGNvbnRhaW5zIGZ1bmN0aW9ucyA8Y29kZT5yYmVuY2htYXJrKCk8L2NvZGU+IHdoaWxlIHRoZSBwYWNrYWdlICoqbWljcm9iZW5jaG1hcmsqKiBoYXMgdGhlIGZ1bmN0aW9uIDxjb2RlPm1pY3JvYmVuY2htYXJrKCk8L2NvZGU+IHdoaWNoIHRha2UgZXhwcmVzc2lvbnMgYXMgcGFyYW1ldGVycyBhbmQgcmVwb3J0IHRoZSBydW4tdGltZSBvZiBlYWNoIG1ha2luZyBjb2RlIGNvbXBhcmlzb25zIHNpbXBsZXIuIFRoZSAqKm1pY3JvYmVuY2htYXJrKiogcGFja2FnZSBhbHNvIGNvbnRhaW5zIHZpc3VhbGl6YXRpb25zIGZvciBiZW5jaG1hcmtzIGJ1aWx0IHVzaW5nICoqZ3Bsb3QyKiouDQoNCiMjIFN1bW1hcnkNCg0KVGhlIG1vc3QgY29tbW9uIGFuZCBzaW1wbGVzdCBhcHByb2FjaCB0byBtZWFzdXJpbmcgdGhlIGV4ZWN1dGlvbiB0aW1lIG9mIGFuIFIgZXhwcmVzc2lvbiBvciBhIGNvZGUgY2h1bmsgaXMgdG8gdXNlIGVpdGhlciA8Y29kZT5TeXMudGltZSgpPC9jb2RlPiBvciA8Y29kZT5zeXN0ZW0udGltZSgpPC9jb2RlPi4NCg0KIyMgRmlsZXMgJiBSZXNvdXJjZXMNCg0KYGBge3IgemlwRmlsZXMsIGVjaG89RkFMU0V9DQp6aXBOYW1lID0gc3ByaW50ZigiTGVzc29uRmlsZXMtJXMtJXMuemlwIiwgDQogICAgICAgICAgICAgICAgIHBhcmFtcyRjYXRlZ29yeSwNCiAgICAgICAgICAgICAgICAgcGFyYW1zJG51bWJlcikNCg0KdGV4dEFMaW5rID0gcGFzdGUwKCJBbGwgRmlsZXMgZm9yIExlc3NvbiAiLCANCiAgICAgICAgICAgICAgIHBhcmFtcyRjYXRlZ29yeSwiLiIscGFyYW1zJG51bWJlcikNCg0KIyBkb3dubG9hZEZpbGVzTGluaygpIGlzIGluY2x1ZGVkIGZyb20gX2luc2VydDJEQi5SDQprbml0cjo6cmF3X2h0bWwoZG93bmxvYWRGaWxlc0xpbmsoIi4iLCB6aXBOYW1lLCB0ZXh0QUxpbmspKQ0KYGBgDQoNCi0tLS0tLS0tLS0tLS0tLS0tLS0tLS0tLS0tLS0tLS0tLS0tLS0tLS0tLS0tLS0tLS0tLS0tLS0tLS0tLS0tLS0tLS0tLS0tLQ0KDQojIyBSZWZlcmVuY2VzDQoNCls1IHdheXMgdG8gbWVhc3VyZSBydW5uaW5nIHRpbWUgb2YgUiBjb2RlXShodHRwczovL3d3dy5hbGV4ZWpnb3NzbWFubi5jb20vYmVuY2htYXJraW5nX3IvIzp+OnRleHQ9JTIwNSUyMHdheXMlMjB0byUyMG1lYXN1cmUlMjBydW5uaW5nJTIwdGltZSUyMG9mLG9mJTIwYW4lMjBSJTIwZXhwcmVzc2lvbiUyMHVzaW5nJTIwc3lzdGVtLnRpbWUuJTIwTW9yZSUyMCkNCg0KIyMgRXJyYXRhDQoNCk5vbmUgY29sbGVjdGVkIHlldC4gTGV0IHVzIGtub3cuDQoNCmBgYHs9aHRtbH0NCjxzY3JpcHQgc3JjPSJodHRwczovL2Zvcm0uam90Zm9ybS5jb20vc3RhdGljL2ZlZWRiYWNrMi5qcyIgdHlwZT0idGV4dC9qYXZhc2NyaXB0Ij4NCiAgbmV3IEpvdGZvcm1GZWVkYmFjayh7DQogICAgZm9ybUlkOiAiMjEyMTg3MDcyNzg0MTU3IiwNCiAgICBidXR0b25UZXh0OiAiRmVlZGJhY2siLA0KICAgIGJhc2U6ICJodHRwczovL2Zvcm0uam90Zm9ybS5jb20vIiwNCiAgICBiYWNrZ3JvdW5kOiAiI0Y1OTIwMiIsDQogICAgZm9udENvbG9yOiAiI0ZGRkZGRiIsDQogICAgYnV0dG9uU2lkZTogImxlZnQiLA0KICAgIGJ1dHRvbkFsaWduOiAiY2VudGVyIiwNCiAgICB0eXBlOiBmYWxzZSwNCiAgICB3aWR0aDogNzAwLA0KICAgIGhlaWdodDogNTAwLA0KICAgIGlzQ2FyZEZvcm06IGZhbHNlDQogIH0pOw0KPC9zY3JpcHQ+DQpgYGANCmBgYHtyIGNvZGU9eGZ1bjo6cmVhZF91dGY4KHBhc3RlMChoZXJlOjpoZXJlKCksJy9SL19kZXBsb3lLbml0LlInKSksIGluY2x1ZGUgPSBGQUxTRX0NCmBgYA0K