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.

Riggall

I don't reproduce on 32 bit Ubuntu 12.04, R-devel (results of sessionInfo() might be helpful -- I get median times of 26 nanoseconds for NULL and 294 nanoseconds for f(). I suspect that your problem is just that the function takes so little time that there is a timing inaccuracy. – Metatarsus

... I don't reproduce under MacOS X.5 R 3.0.2 either (I don't have access to a Windows system at the moment) – Metatarsus

The timing function calls QPC on Windows. I do not know if your OS is calling RDTSC to fulfill QPC (some releases do). If so, and you're running an ancient multicore or multi-CPU (Core 2 or earlier), RDTSC can see time regressions when the process jumps between cores. – Twoedged

Have you contacted the package author? – Cordula

Eventually I did (just right now). Thank You for an admonition! – Riggall

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.

Contemplative

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).

Nickolas

thank you for your explanation and a suggestion how to fix it! I have installed the updates/new drivers that The Intel® Driver Update Utility suggested for my computer and I keep getting the same error. Temporarily I am simply moving to rbenchmark, it does work with my PC. – Riggall

A way to specify process affinity on Windows is by using start with the /affinity flag to create the process. start /affinity 1 R for example, to keep the process on core 0. – Twoedged

I've followed the MatthewLundberg's hint and antiduh's guide how to make a change in Windows 7, narrowing down the number of processors in use to one ([1]) for the rstudio.exe *32 (rsession.exe changed by itself then), then running restart R in RStudio, then checking once again if processors number reduction was kept (it was), then running the microbenchmark code once again. Unfortunately, I have received the same error. [1]: dropbox.com/s/ob51pwm8fy83nmp/… – Riggall

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)

Wolsky