A Short Introduction to rcpptimer

This package provides a simple timer for Rcpp code. The interface resembles the tictoc R package. The package wraps cpptimer, a header-only library that contains a class called CppTimer. rcpptimer adds this class as Timer to the Rcpp namespace.

This introduction explains how to use Rcpp::Timer with Rcpp::cppFunction and how:

Initialize a Timer

Initializing a timer is simple. There are four constructors available. The default constructor initializes a timer with warnings enabled that will write the results as data.frame called “times” to the R environment:

Rcpp::Timer timer; // default constructor
Rcpp::Timer timer("my_timer"); // Set a custom name for the results
Rcpp::Timer timer(false); // Disable warnings
Rcpp::Timer timer("my_timer", false); // Set a custom name and disable warnings

Below and throughout other vignettes, we will use all four as needed.

Straightforward Example

With Rcpp::cppFunction, we must add the depends argument to the function to tell the compiler we want to link the ‘rcpptimer’ library to the C++ code. Then, we can construct an instance of the Timer class and use the tic and toc methods to measure the time it takes to execute a code block. Here, we allocate some memory to have something to measure:

Rcpp::cppFunction("
double add(double &x, double &y)
{
 Rcpp::Timer timer;
 timer.tic();
 double z = x + y;
 timer.toc();
 return(z);
}",
  depends = "rcpptimer"
)

add(rnorm(1), runif(1))
#> [1] 1.006532

This function will automatically write a data frame called “times” to the R environment. Read more about that autoreturn feature (i.e., how to assign a custom variable name and how to manually handle the results) in vignette("autoreturn").

The resulting times object has two classes: data.frame and rcpptimer. We provide a custom S3 method for printing the results. If it is registered, it may scale the results to improve readability (see rcpptimer::print.rcpptimer). Otherwise, it will print the results using base::print.data.frame.

print(times)
#>        Nanoseconds SD Min Max Count
#> tictoc         666  0 666 666     1

Multiple Timers

You can also use multiple timers in the same function. The Timers can be nested and overlapping. Just pass a string to the tic and toc methods to distinguish the timers:

Rcpp::cppFunction('
double add(double &x, double &y)
{
 Rcpp::Timer timer;
 timer.tic("body");
 timer.tic("add_1");
 timer.tic("add_2");
 double z = x + y;
 timer.toc("add_1");
 timer.toc("add_2");
 timer.toc("body");
 return(z);
}',
  depends = "rcpptimer"
)

add(rnorm(1), runif(1))
#> [1] -0.06800712

print(times)
#>       Microseconds SD   Min   Max Count
#> add_1        0.867  0 0.867 0.867     1
#> add_2        0.651  0 0.651 0.651     1
#> body         2.317  0 2.317 2.317     1

rcpptimer will group multiple timers with the same name and calculate summary statistics for them. Consider this more advanced example, which also uses OpenMP:

// fibonacci.cpp
std::vector<long int> fibonacci_omp(std::vector<long int> n)
{

  Rcpp::Timer timer;

  // This scoped timer measures the total execution time of 'fibonacci'
  Rcpp::Timer::ScopedTimer scpdtmr(timer, "fib_body");

  std::vector<long int> results = n;

#pragma omp parallel for
  for (unsigned int i = 0; i < n.size(); ++i)
  {
    timer.tic("fib_" + std::to_string(n[i]));
    results[i] = fib(n[i]);
    timer.toc("fib_" + std::to_string(n[i]));
  }

  return (results);
}

This function is included in rcpptimer, so we can execute it right away:

results <- rcpptimer::fibonacci_omp(n = rep(20:25, 10))
print(times)
#>          Microseconds     SD     Min     Max Count
#> fib_20         55.630 60.174  10.486 189.134    10
#> fib_21         28.135 19.186  15.365  81.455    10
#> fib_22         63.192 33.412  32.448 125.883    10
#> fib_23         59.154 10.114  45.242  81.912    10
#> fib_24        102.646 18.260  82.260 138.242    10
#> fib_25        126.116 17.808  98.842 148.609    10
#> fib_body      786.503  0.000 786.503 786.503     1

Timing Scopes with Rcpp::Timer::ScopedTimer

The ScopedTimer lets you measure the execution time of scopes. It will call ..tic() upon creation and .toc() upon destruction. Consider the simple example below:

Rcpp::cppFunction('
double add(double &x, double &y)
{
 Rcpp::Timer timer;
 Rcpp::Timer::ScopedTimer scoped_timer(timer, "add");
 double z = x + y;
 return(z);
}',
  depends = "rcpptimer"
)

add(rnorm(1), runif(1))
#> [1] 0.6249268

print(times)
#>     Microseconds SD   Min   Max Count
#> add        1.114  0 1.114 1.114     1

Note that you only need to initialize the ScopedTimer. Once it goes out of scope, the timer will automatically be stopped.

Warnings and how to Disable them

The default setting will warn about timers that have been started using .tic but never stopped using .toc() and vice versa. This is useful to catch unmatched .tic() and .toc() calls that may be unmatched due to missing statements or typos.

For example, the following code will produce two warnings:

Rcpp::cppFunction('
double add(double &x, double &y)
{
 Rcpp::Timer timer;
 Rcpp::Timer::ScopedTimer scoped_timer(timer, "add");
 timer.tic("add");
 double z = x + y;
 timer.toc("ad");
 return(z);
}',
  depends = "rcpptimer"
)

add(rnorm(1), runif(1))
#> Warning in add(rnorm(1), runif(1)): Timer "ad" not started yet. 
#> Use tic("ad") to start the timer.
#> [1] 0.05678976

Note that this does not affect terminated timers such as ‘mem’.

print(times)
#>     Nanoseconds SD Min Max Count
#> add         623  0 623 623     1

These warnings occur at runtime. Unfortunately, we can’t check for this at compile time.

However, you can turn off these warnings by passing false to the constructor. This is useful if you need .toc() calls in code blocks that may not get executed, e.g. in conditional statements. The example below will not produce any warnings:

Rcpp::cppFunction('
double add(double &x, double &y)
{
 Rcpp::Timer timer(false);
 Rcpp::Timer::ScopedTimer scoped_timer(timer, "add");
 timer.tic("add");
 double z = x + y;
 timer.toc("ad");
 return(z);
}',
  depends = "rcpptimer"
)

add(rnorm(1), runif(1))
#> [1] 1.33853

print(times)
#>     Nanoseconds SD Min Max Count
#> add         442  0 442 442     1