[logback-dev] Intermittent failure on durationOfDisabledLog_NoParameters

[Marshall Pierce]

When running a 'mvn package' from the top level of the logback project, 
I'm getting intermittent failure on durationOfDisabledLog_NoParameters 
in LoggerPerfTest. My computer is quite fast (i7 2600K, 8GB, linux 
3.0.4, jdk 1.6u27)

When I run the test by itself from my IDE, it passes with the following 
output:

durationOfDisabledLog_NoParameters=2.0
Host runs at 96906.22045874437 BIPS
currentBIPS=84956.35367330034 BIPS

The test also succeeds when I run mvn with -Dtest=LoggerPerfTest 
-DfailIfNoTests=false.

Contents of the surefire report from one such failure:

-------------------------------------------------------------------------------
Test set: ch.qos.logback.classic.LoggerPerfTest
-------------------------------------------------------------------------------
Tests run: 6, Failures: 1, Errors: 0, Skipped: 0, Time elapsed: 1.589 
sec <<< FAILURE!
durationOfDisabledLogsWith_1_NOPFilter(ch.qos.logback.classic.LoggerPerfTest) 
  Time elapsed: 0.026 sec
durationOfIsDebugEnabled(ch.qos.logback.classic.LoggerPerfTest)  Time 
elapsed: 0.1 sec
durationOfDisabledLog_NoParameters(ch.qos.logback.classic.LoggerPerfTest) 
Time elapsed: 0.19 sec  <<< FAILURE!
junit.framework.AssertionFailedError: current duration 6.0 exceeded 
expected 1.8218115000000001 (adjusted reference), 18 (raw reference)
	at org.slf4j.helpers.BogoPerf.assertDuration(BogoPerf.java:121)
	at 
ch.qos.logback.classic.LoggerPerfTest.durationOfDisabledLog_NoParameters(LoggerPerfTest.java:101)
	at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
	at 
sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39)
	at 
sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
	at java.lang.reflect.Method.invoke(Method.java:597)
	at 
org.junit.runners.model.FrameworkMethod$1.runReflectiveCall(FrameworkMethod.java:44)
	at 
org.junit.internal.runners.model.ReflectiveCallable.run(ReflectiveCallable.java:15)
	at 
org.junit.runners.model.FrameworkMethod.invokeExplosively(FrameworkMethod.java:41)
	at 
org.junit.internal.runners.statements.InvokeMethod.evaluate(InvokeMethod.java:20)
	at 
org.junit.internal.runners.statements.RunBefores.evaluate(RunBefores.java:28)
	at 
org.junit.runners.BlockJUnit4ClassRunner.runNotIgnored(BlockJUnit4ClassRunner.java:79)
	at 
org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:71)
	at 
org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:49)
	at org.junit.runners.ParentRunner$3.run(ParentRunner.java:193)
	at org.junit.runners.ParentRunner$1.schedule(ParentRunner.java:52)
	at org.junit.runners.ParentRunner.runChildren(ParentRunner.java:191)
	at org.junit.runners.ParentRunner.access$000(ParentRunner.java:42)
	at org.junit.runners.ParentRunner$2.evaluate(ParentRunner.java:184)
	at org.junit.runners.ParentRunner.run(ParentRunner.java:236)
	at 
org.apache.maven.surefire.junit4.JUnit4TestSet.execute(JUnit4TestSet.java:59)
	at 
org.apache.maven.surefire.suite.AbstractDirectoryTestSuite.executeTestSet(AbstractDirectoryTestSuite.java:120)
	at 
org.apache.maven.surefire.suite.AbstractDirectoryTestSuite.execute(AbstractDirectoryTestSuite.java:103)
	at org.apache.maven.surefire.Surefire.run(Surefire.java:169)
	at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
	at 
sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39)
	at 
sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
	at java.lang.reflect.Method.invoke(Method.java:597)
	at 
org.apache.maven.surefire.booter.SurefireBooter.runSuitesInProcess(SurefireBooter.java:350)
	at 
org.apache.maven.surefire.booter.SurefireBooter.main(SurefireBooter.java:1021)

durationOfDisabledLog_1_Parameter(ch.qos.logback.classic.LoggerPerfTest) 
  Time elapsed: 0.017 sec
durationOfEnabledLog(ch.qos.logback.classic.LoggerPerfTest)  Time 
elapsed: 0 sec
testThreadedLogging(ch.qos.logback.classic.LoggerPerfTest)  Time 
elapsed: 1.254 sec