When using Microbenchmark I have noticed that the first execution is always a lot slower than the rest. This effect was the same over different machines and with different functions. Does this have something to do with with the library or is this some kind of warmup that is to be expected?
library(microbenchmark)
X <- matrix(rnorm(100), nrow = 10)
microbenchmark(solve(X))$time
#[1] 82700 23700 18300 17700 19700 19100 16900 17500 17300 16600 16700 16700 18500 16900 17700 16900 17000 16200 17400 17000 16800 16600 17000 16700 16800 17100
#[27] 17300 17100 16800 17800 17400 18100 17400 18100 18000 16700 17400 17300 17000 16800 16400 17300 16700 16900 16900 16700 17200 17800 16600 17100 16800 17800
#[53] 17000 17200 17500 17200 17200 17300 17800 17600 17600 17200 16600 16700 16800 16600 16400 16500 17300 17600 16800 17600 16300 16800 17100 16500 16800 16700
#[79] 16300 16700 16300 16700 16800 16700 16400 17100 16400 17100 17000 18000 16600 16600 16600 16800 16700 16500 17600 19100 17400 16900
It has to do with the warm-up time, see help('microbenchmark'), section details, argument control:
The control list can contain the following entries:
order
[omited]warmup
the number of warm-up iterations performed before the actual benchmark. These are used to estimate the timing overhead as well as spinning up the processor from any sleep or idle states it might be in. The default value is 2.
If you increase the number of warm-up iterations, the first run might not be the slowest, though it many times is.
library(microbenchmark)
set.seed(2020)
X <- matrix(rnorm(100), nrow = 10)
times <- microbenchmark(solve(X), control = list(warmup = 10))$time
times
# [1] 145229 72724 65333 65305 115715 63797 689113 72101 64830 66392
# [11] 65776 66619 65531 64765 65351 65605 65745 65106 64661 65790
# [21] 65435 64964 66138 65952 66893 65654 65585 75141 74666 69060
# [31] 72725 66650 65486 65894 66808 65381 66039 65959 64842 65029
# [41] 65673 66439 64394 70585 68899 73875 73180 67807 65891 65699
# [51] 64693 63679 65504 80190 66150 65048 64372 64842 65845 65144
# [61] 65543 65297 65485 64695 66580 64921 65453 64840 65559 65805
# [71] 64362 66098 65464 65227 64998 64007 65659 63919 64727 64796
# [81] 65231 64030 65871 65735 64217 65195 65181 65130 66015 63891
# [91] 63755 65274 65116 64573 64244 64214 64148 64457 65346 64228
Now see which is the first with order:
order(times, decreasing = TRUE)
# [1] 7 1 5 54 28 29 46 47 31 2 8 44 30 45 48 25 35 32 12
# [20] 65 42 10 55 23 72 37 89 38 24 34 49 83 59 70 20 11 17 84
# [39] 50 41 77 26 16 27 69 61 13 53 33 63 73 67 21 36 15 99 3
# [58] 4 62 92 81 74 86 87 60 88 93 18 56 40 75 22 66 39 58 68
# [77] 9 80 14 79 64 51 19 94 98 43 57 71 95 100 85 96 97 82 76
# [96] 78 90 6 91 52
In this case the slowest was the seventh run, not the first.