Why the 'Measured negative execution time!' error appears? (And how to deal with it?)

Question

I am getting to know some of the microbenchmark R package's featrues. I implemented a sample code from this publication of Hadley Wickham and received an error I cannot find any precise information about and I cannot deal with. Thank you in advance for any explanation / hint etc.

An example code:

library(microbenchmark)

f <- function() NULL
microbenchmark(
  NULL,
  f()
)

Console output:

Error in microbenchmark(NULL, f()) : 
  Measured negative execution time! Please investigate and/or contact the package author.

UPDATE. Here is my seesionInfo() console output:

> sessionInfo()
R version 3.0.2 (2013-09-25)
Platform: x86_64-w64-mingw32/x64 (64-bit)

locale:
[1] LC_COLLATE=Polish_Poland.1250  LC_CTYPE=Polish_Poland.1250    LC_MONETARY=Polish_Poland.1250
[4] LC_NUMERIC=C                   LC_TIME=Polish_Poland.1250    

attached base packages:
[1] stats     graphics  grDevices utils     datasets  methods   base     

other attached packages:
[1] ggplot2_0.9.3.1      microbenchmark_1.3-0

loaded via a namespace (and not attached):
 [1] colorspace_1.2-4   dichromat_2.0-0    digest_0.6.3       grid_3.0.2         gtable_0.1.2       labeling_0.2      
 [7] MASS_7.3-29        munsell_0.4.2      plyr_1.8           proto_0.3-10       RColorBrewer_1.0-5 reshape2_1.2.2    
[13] scales_0.2.3       stringr_0.6.2      tools_3.0.2    

UPDATE 2. Some further information the author of the package asked me for:

• R variable R.version

  R.version _
  platform x86_64-w64-mingw32
  arch x86_64
  os mingw32
  system x86_64, mingw32
  status
  major 3
  minor 0.2
  year 2013
  month 09
  day 25
  svn rev 63987
  language R
  version.string R version 3.0.2 (2013-09-25) nickname Frisbee Sailing

• make, model and speed of the CPU in my computer:

Processor: Intel(R) Core(TM) i7-2600K CPU @ 3.40GHz 3.70 GHz

RAM: 16,0 GB

System type: 64-bits

UPDATE 3.

I have noticed that one of the modifications of the code above does return a correct result:

> ### 1 
> f <- function(){NULL} 
> microbenchmark(NULL, f())
Error in microbenchmark(NULL, f()) : 
  Measured negative execution time! Please investigate and/or contact the package author.
> 
> 
> ### 2 
> f <- function(){ } 
> microbenchmark(NULL, f())
Error in microbenchmark(NULL, f()) : 
  Measured negative execution time! Please investigate and/or contact the package author.
> 
> 
> ### 3 
> f <- function(){NULL} 
> microbenchmark(f())
Unit: nanoseconds
 expr min lq median uq  max neval
  f()   0  1      1  1 7245   100
> 
> ### 4 
> f <- function(){ } 
> microbenchmark(f())
Error in microbenchmark(f()) : 
  Measured negative execution time! Please investigate and/or contact the package author.

Answer 1

As the other answer stated, it seems that the Windows timer does not have enough precision to measure execution time, i.e. execution time is < 1 nanosecond. If we make a simple change to the source of the package in the nanotimer.c file to the do_microtiming() C function...

if (start < end) {
    const nanotime_t diff = end - start;
    if (diff < overhead) {
        ret[i] = R_NaReal;
        n_under_overhead++;
    } else {
        ret[i] = diff - overhead;
    }
} else if( start == end ) { // <----- This elseif is our minor edit
  error( "Start and end have same time. Not enough precision to measure execution time" );
} else {
    error("Measured negative execution time! Please investigate and/or "
          "contact the package author.");
}

And then test it out...

f <- function() NULL
microbenchmark( f() )
#Error in microbenchmark(f()) : 
#  Start and end have same time. Not enough precision to measure execution time

It seems that you can't measure sub nanosecond times on yours (and mine) Windows system with current drivers.

So execution time is not negative, it's just so small you cannot measure it.

Answer 2

Depending on what operating system you're using, there may be a problem with the installed drivers for the High Performance Timer subsystem on your computer.

In Windows land, one accesses the HPT through the QueryPerformanceCounter and QueryPerformanceFrequency functions. QPF tells you how frequently the counter ticks and thus tells you the accuracy of the counter; QPC / QPF gives you a value in seconds, usually of how long the computer has been booted.

The problem is that driver support for this API is sometimes spotty. AMD particularly has had trouble in the past, I've personally experienced this.

You can try searching online for drivers for your CPU and/or motherboard to see if you're missing drivers. That may fix this.

Edit:

@MatthewLundberg is on point about the rdtsc instruction on different cores sometimes being slightly off. One cheap way to get around this is to change the cpu affinity for the program so that it only runs on one core.

Assuming you're on Win Vista or later, go into Task Manager, right click the process that is running your code, select 'Affinity...' and restrict it to only one processor (the first CPU is fine).

Answer 3

Another way to work around this problem is by increasing the amount of work for the expression that you benchmark. I ran into the same issue while trying to understand how the microbenchmark function works and avoided the problem by changing the expressions (test functions f1, f2, and f3) into something more challenging:

library(microbenchmark)

f1 <- function() { factorial(10) }
f2 <- function() { 2 * 3 * 4 * 5 * 6 * 7 * 8 * 9 * 10 }
f3 <- function() { factorial(16) / (11 * 12 * 13 * 14 * 15 * 16) }
benchmarkResults <- microbenchmark(f1(), f2(), f3(), times = 1000L)
print(benchmarkResults)