Measuring Function Execution Time in R

get execution time in milliseconds in R

1) Timing is operating-system dependent. On Windows you may only get milliseconds.

2) No need to define tic() and toc(), R has system.time(). Here is an example:

R> system.time(replicate(100, sqrt(seq(1.0, 1.0e6))))
   user  system elapsed 
  2.210   0.650   2.867 
R> 

3) There are excellent add-on packages rbenchmark and microbenchmark.

3.1) rbenchmark is particularly useful for comparison of commands, but can also be used directly:

R> library(rbenchmark)
R> x <- seq(1.0, 1.0e6); benchmark(sqrt(x), log(x))
     test replications elapsed relative user.self sys.self user.child sys.child
2  log(x)          100   5.408  2.85835      5.21     0.19          0         0
1 sqrt(x)          100   1.892  1.00000      1.62     0.26          0         0
R>

3.2) microbenchmark excels at highest precision measurements:

R> library(microbenchmark)
R> x <- seq(1.0, 1.0e6); microbenchmark(sqrt(x), log(x))
Unit: nanoseconds
     expr      min       lq   median       uq      max
1  log(x) 50589289 50703132 55283301 55353594 55917216
2 sqrt(x) 15309426 15412135 15452990 20011418 39551819
R> 

and this last one, particularly on Linux, already gives you nano-seconds. It can also plot results etc so have a closer look at that package.

Is difference of Sys.time() a reliable execution time estimate in R?

Here is the output I tried

First example - the calculation output is 2.2... and it's in second.

> start <- Sys.time()
> Sys.sleep(2)
> end <- Sys.time()
> print(paste('Time difference :', end-start))
[1] "Time difference : 2.20864367485046"
> difftime(end, start, units = "mins")
Time difference of 0.03681073 mins

Second example - the calculation output is 1.77... and it is in minutes

> start <- Sys.time()
> x <- matrix(rnorm(7500000), nrow=500, ncol=15000)
> x <- cor(x)
> end <- Sys.time()
> print(paste('Time difference :', end-start))
[1] "Time difference : 1.77510009209315"
> difftime(end, start, units = "mins")
Time difference of 1.7751 mins

You can see that the Time difference you output is actually in minutes but it doesn't state that is minutes or seconds so that it confusing. I recommend you use the difftime() function instead.

How to measure the execution time of a code without actually running the code in R?

Try running your code on smaller problems to see how it scales

> fun0 = function(n) { x = integer(); for (i in seq_len(n)) x = c(x, i); x }
> p = microbenchmark(fun0(1000), fun0(2000), fun0(4000), fun0(8000), fun0(16000),
+                    times=20)
> p
Unit: milliseconds
        expr        min         lq       mean     median         uq        max
  fun0(1000)   1.627601   1.697958   1.995438   1.723522   2.289424   2.935609
  fun0(2000)   5.691456   6.333478   6.745057   6.928060   7.056893   8.040366
  fun0(4000)  23.343611  24.487355  24.987870  24.854968  25.554553  26.088183
  fun0(8000)  92.517691  95.827525 104.900161  97.305930 112.924961 136.434998
 fun0(16000) 365.495320 369.697953 380.981034 374.456565 390.829214 411.203191
 neval
    20
    20
    20
    20
    20

Doubling the problem size leads to exponentially slower execution; visualize as

library(ggplot2)
ggplot(p, aes(x=expr, y=log(time))) + geom_point() + 
    geom_smooth(method="lm", aes(x=as.integer(expr)))

This is terrible news for big problems!

Investigate alternative implementations that scale better while returning the same answer, both as the problem increases in size and at a given problem size. First make sure your algorithms / implementations get the same answer

> ## linear, ok
> fun1 = function(n) { x = integer(n); for (i in seq_len(n)) x[[i]] = i; x }
> identical(fun0(100), fun1(100))
[1] TRUE

then see how the new algorithm scales with problem size

> microbenchmark(fun1(100), fun1(1000), fun1(10000))
Unit: microseconds
        expr      min       lq      mean    median         uq       max neval
   fun1(100)   86.260   97.558  121.5591  102.6715   107.6995  1058.321   100
  fun1(1000)  845.160  902.221  932.7760  922.8610   945.6305  1915.264   100
 fun1(10000) 8776.673 9100.087 9699.7925 9385.8560 10310.6240 13423.718   100

Explore more algorithms, especially those that replace iteration with vectorization

> ## linear, faster -- *nano*seconds
> fun2 = seq_len
> identical(fun1(100), fun2(100))
[1] TRUE
> microbenchmark(fun2(100), fun2(1000), fun2(10000))
Unit: nanoseconds
        expr   min      lq     mean median    uq   max neval
   fun2(100)   417   505.0   587.53    553   618  2247   100
  fun2(1000)  2126  2228.5  2774.90   2894  2986  5511   100
 fun2(10000) 19426 19741.0 25390.93  27177 28209 43418   100

Comparing algorithms at specific sizes

> n = 1000; microbenchmark(fun0(n), fun1(n), fun2(n), times=10)
Unit: microseconds
    expr      min       lq      mean    median       uq      max neval
 fun0(n) 1625.797 1637.949 2018.6295 1657.1195 2800.272 2857.400    10
 fun1(n)  819.448  843.988  874.9445  853.9290  910.871 1006.582    10
 fun2(n)    2.158    2.386    2.5990    2.6565    2.716    3.055    10
> n = 10000; microbenchmark(fun0(n), fun1(n), fun2(n), times=10)
Unit: microseconds
    expr        min         lq        mean      median         uq        max
 fun0(n) 157010.750 157276.699 169905.4745 159944.5715 192185.973 197389.965
 fun1(n)   8613.977   8630.599   9212.2207   9165.9300   9394.605  10299.821
 fun2(n)     19.296     19.384     20.7852     20.8595     21.868     22.435
 neval
    10
    10
    10

shows the increasing importance of a sensible implementation as problem size increases.

How to measure execution time of code in device+OpenCL+GPU

A good start is to format your code so you have consistent indentation. I have done that for you here. If you are using Visual Studio Community, select the text and press Ctrl+K and then Ctrl+F.

Now to the profiling. Here is a simple Clock class that is easy to use for profiling:

#include <chrono>
class Clock {
private:
    typedef chrono::high_resolution_clock clock;
    chrono::time_point<clock> t;
public:
    Clock() { start(); }
    void start() { t = clock::now(); }
    double stop() const { return chrono::duration_cast<chrono::duration<double>>(clock::now()-t).count(); }
};

With that prepared, here is how you profile your GPU kernel:

Clock clock;
clock.start();
status = clEnqueueNDRangeKernel(queue, kernel, dim, nullptr, global_size, local_size, 0, nullptr, &event);
clFinish(queue); // important: this will block until kernel execution is finished
std::cout << "Execution time: " << clock.stop() << " seconds" << std::endl;

To get a more accurate measurement, you can measure kernel execution time multiple times in a loop and calculate the average.

---

Related Topics