[Rd] function call overhead

[Olaf Mersmann]

Dear Hadly, dear list,

On Wed, Feb 16, 2011 at 9:53 PM, Hadley Wickham <hadley at rice.edu> wrote:
> I wondered about this statement too but:
>
>> system.time(replicate(1e4, base::print))
>   user  system elapsed
>  0.539   0.001   0.541
>> system.time(replicate(1e4, print))
>   user  system elapsed
>  0.013   0.000   0.012

These timings are skewed. Because I too have wondered about this in
the past, I recently published the microbenchmark package which tries
hard to accurately time it takes to evaluate some expression(s). Using
this package I get:

> library("microbenchmark")
> res <- microbenchmark(print, base::print, times=10000)
> res
Unit: nanoeconds  ## I've fixed the typo, but not pushed to CRAN
              min    lq  median    uq     max
print          57    65    68.0    69   48389
base::print 41763 43357 44278.5 48403 4749851

A better way to look at this is by converting to evaluations per second:

> print(res, unit="eps")
Unit: evaluations per second
                    min          lq      median          uq        max
print       17543859.65 15384615.38 14705882.35 14492753.62 20665.8538
base::print    23944.64    23064.33    22584.32    20659.88   210.5329

Resolving 23000 names per second or ~15M ist quite a dramatic
difference in my world. The timings obtained by

>  system.time(replicate(1e4, base::print))
       User      System verstrichen
      0.475       0.006       0.483
>  system.time(replicate(1e4, print))
       User      System verstrichen
      0.011       0.001       0.014

are skewed by the overhead of replicate() in this case because the
execution time of the expression under test is so short.

Cheers,
Olaf Mersmann