Why is the first run of microbenchmark always the slowest?

Question

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

Answer 1

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.