Timing info for testcases in Junit runner seems invalid?

[Jeppe Nejsum Madsen]

Hi,

I'm trying to make our build faster and would like to pinpoint the
slowest tests. But it seems the output from the JUnit runner is not
correct. Here's an excerpt:

<testsuite errors="0" failures="0" hostname="jnmmbp.local"
name="fleetzone.integrationtest.excel.ExcelParserSpec" tests="15"
time="8.974" timestamp="2012-06-11T10:14
:31">
<properties />
<testcase classname="fleetzone.integrationtest.excel.ExcelParserSpec"
name="An invalid file should::return failure" time="0.0010" />
<testcase classname="fleetzone.integrationtest.excel.ExcelParserSpec"
name="An file with same column twice should::return error" time="0.0"
/>
<testcase classname="fleetzone.integrationtest.excel.ExcelParserSpec"
name="An Excel 2003 file should::be readable" time="0.0" />
<testcase classname="fleetzone.integrationtest.excel.ExcelParserSpec"
name="An Excel 2003 file should::parse header in first row"
time="0.0020" />
<testcase classname="fleetzone.integrationtest.excel.ExcelParserSpec"
name="An Excel 2003 file should::trim header values" time="0.0" />
<testcase classname="fleetzone.integrationtest.excel.ExcelParserSpec"
name="An Excel 2003 file should::iterate over all non-blank rows"
time="0.0" />
<testcase classname="fleetzone.integrationtest.excel.ExcelParserSpec"
name="An Excel 2003 file should::ignore case when filtering columns"
time="0.0" />
<testcase classname="fleetzone.integrationtest.excel.ExcelParserSpec"
name="An Excel 2003 file should::trim cell values" time="0.0" />
<testcase classname="fleetzone.integrationtest.excel.ExcelParserSpec"
name="An Excel 2003 file should::parse string cells with numeric
content correct" time="0.001
0" />
<testcase classname="fleetzone.integrationtest.excel.ExcelParserSpec"
name="An Excel 2003 file should::parse numeric cells correct"
time="0.0" />
<testcase classname="fleetzone.integrationtest.excel.ExcelParserSpec"
name="An Excel 2003 file should::use formula results for formula
cells" time="0.0010" />
<testcase classname="fleetzone.integrationtest.excel.ExcelParserSpec"
name="An Excel 2003 file should::list columns not imported" time="0.0"
/>
<testcase classname="fleetzone.integrationtest.excel.ExcelParserSpec"
name="An Excel 2003 file should::list rows with failures" time="0.0"
/>
<testcase classname="fleetzone.integrationtest.excel.ExcelParserSpec"
name="An Excel 2003 file should::handle error cells gracefully"
time="0.0" />
<testcase classname="fleetzone.integrationtest.excel.ExcelParserSpec"
name="An Excel 2003 file should::stop parsing when max number of error
rows are reached" time
="0.0" />

Note that the total time seems correct but the individual testcase
times are too low

I know I reported this for specs and there was not much to be done,
but it seems to be a problem for specs2 as well :-(

/Jeppe

[etorreborre]

Is it a sequential specification? What's the output for a sequential one?

[Jeppe Nejsum Madsen]

On Mon, Jun 11, 2012 at 2:24 PM, etorreborre <etorr...@gmail.com> wrote:
> Is it a sequential specification? What's the output for a sequential one?

Not sure :-) Using the default mutable Specification with the JUnitRunner.

Adding args(sequential=true) doesn't change the result.

To add a little detail, I'm running the tests using Gradle which finds
the JUnit test suites automagically. So I'm not sure how much of the
specs2 machinery is being used to execute & generate the output.....

Is there a way to verify?

/Jeppe

[etorreborre]

I think I know where the problem is, but I need some time to fix it.

In the meantime can you use sbt and the "junitxml" argument to produce the xml files?

E.

[Jeppe Nejsum Madsen]

On Tue, Jun 12, 2012 at 11:37 AM, etorreborre <etorr...@gmail.com> wrote:
> I think I know where the problem is, but I need some time to fix it.

That's good (the first part at least :-)

> In the meantime can you use sbt and the "junitxml" argument to produce the
> xml files?

Yeah maybe, I'll look into this....

/Jeppe

[etorreborre]

This issue should be fixed now with the latest 1.12-SNAPSHOT.

[Diego Medina]

On Tue, Jun 12, 2012 at 8:43 AM, etorreborre <etorr...@gmail.com> wrote:
> This issue should be fixed now with the latest 1.12-SNAPSHOT.
>

So when you said you needed some time to fix it, you meant in 3 hours
would you have a solution?, wow.

Diego

>
> On Tuesday, June 12, 2012 10:01:16 PM UTC+10, Jeppe Nejsum Madsen wrote:
>>
>> On Tue, Jun 12, 2012 at 11:37 AM, etorreborre <etorr...@gmail.com>
>> wrote:
>> > I think I know where the problem is, but I need some time to fix it.
>>
>> That's good (the first part at least :-)
>>
>> > In the meantime can you use sbt and the "junitxml" argument to produce
>> > the
>> > xml files?
>>
>> Yeah maybe, I'll look into this....
>>
>> /Jeppe

--
Diego Medina
Lift/Scala Developer
di...@fmpwizard.com
http://www.fmpwizard.com

[Daniel Sobral]

On Tue, Jun 12, 2012 at 11:13 AM, Diego Medina <di...@fmpwizard.com> wrote:
> On Tue, Jun 12, 2012 at 8:43 AM, etorreborre <etorr...@gmail.com> wrote:
>> This issue should be fixed now with the latest 1.12-SNAPSHOT.
>>
>
> So when you said you needed some time to fix it, you meant in 3 hours
> would you have a solution?, wow.

I also have always thought Eric uses different time units than the
rest of us. :-)

>
>  Diego
>
>>
>> On Tuesday, June 12, 2012 10:01:16 PM UTC+10, Jeppe Nejsum Madsen wrote:
>>>
>>> On Tue, Jun 12, 2012 at 11:37 AM, etorreborre <etorr...@gmail.com>
>>> wrote:
>>> > I think I know where the problem is, but I need some time to fix it.
>>>
>>> That's good (the first part at least :-)
>>>
>>> > In the meantime can you use sbt and the "junitxml" argument to produce
>>> > the
>>> > xml files?
>>>
>>> Yeah maybe, I'll look into this....
>>>
>>> /Jeppe
>
>
>
> --
> Diego Medina
> Lift/Scala Developer
> di...@fmpwizard.com
> http://www.fmpwizard.com

--
Daniel C. Sobral

I travel to the future all the time.

[Jeppe Nejsum Madsen]

On Tue, Jun 12, 2012 at 2:43 PM, etorreborre <etorr...@gmail.com> wrote:
> This issue should be fixed now with the latest 1.12-SNAPSHOT.

Thanks, but I still can't get the correct values. Just tried with a
little more systematic approach:

@RunWith(classOf[JUnitRunner])
class SerializersSpec extends mutable.Specification {
args(sequential=true)
val s = CaseObjectSerializer[MyTrait] {
case "O1" => O1
case "O2" => O2
}

"CaseObjectSerializer" should {
"correctly write/read case class containing case objects" in {
implicit val formats = Serialization.formats(NoTypeHints) + s

val orig = C(42, O1)
val written = Serialization.write(orig)

val read = Serialization.read[C](written)

read must_== orig
}

"wait 3 secs" in {
Thread.sleep(3000)
1 must_== 1
}

"wait 6 secs" in {
Thread.sleep(6000)
1 must_== 1
}
}
}

Running this as a JUnit test in Eclipse gives the following timings:

Total 8.979s
correctly write....: 2.97s
wait 3s: 6.001s
wait 6s: 0.003s

The generated xml contains this:

?xml version="1.0" encoding="UTF-8"?>

<testsuite errors="0" failures="0" hostname="jnmmbp.local"

name="fleetzone.unittest.SerializersSpec" tests="6" time="0.096"
timestamp="2012-06-12T16:19:49">
<properties />
<ignored-testcase classname="fleetzone.unittest.SerializersSpec"
name="CaseObjectSerializer should::correctly write/read case class
containing case objects" time="0.0" />
<testcase classname="fleetzone.unittest.SerializersSpec"
name="CaseObjectSerializer should::correctly write/read case class
containing case objects" time="0.0080" />
<ignored-testcase classname="fleetzone.unittest.SerializersSpec"
name="CaseObjectSerializer should::wait 3 secs" time="0.0" />
<testcase classname="fleetzone.unittest.SerializersSpec"
name="CaseObjectSerializer should::wait 3 secs" time="0.0" />
<ignored-testcase classname="fleetzone.unittest.SerializersSpec"
name="CaseObjectSerializer should::wait 6 secs" time="0.0" />
<testcase classname="fleetzone.unittest.SerializersSpec"
name="CaseObjectSerializer should::wait 6 secs" time="0.0" />
<system-out><![CDATA[]]></system-out>
<system-err><![CDATA[]]></system-err>
</testsuite>

Note both the timings and the number of tests reported...

/Jeppe

[etorreborre]

So now everyone knows why I was so fast, I was just wrong :-)!

I thought I had a proper quick fix but I only tested it by instrumenting my code, not really by running the code through a real JUnit plugin, like the surefire maven plugin.

I also initially said that it would take some time because a more important refactoring was necessary. Indeed, I realized that the JUnitRunner was more or less always forcing the sequential execution of specs.

The net result of all this is that:

 * I refactored the JUnitRunner

 * the timings should display properly now (I tested it with Maven)

 * the specifications can now run concurrently (so you should see improved times if you don't include the "sequential" argument)

I pushed a new 1.12-SNAPSHOT with all this, thanks for confirming that the situation is indeed better.

Eric.

[Jeppe Nejsum Madsen]

On Wed, Jun 13, 2012 at 3:12 PM, etorreborre <etorr...@gmail.com> wrote:
> So now everyone knows why I was so fast, I was just wrong :-)!
>
> I thought I had a proper quick fix but I only tested it by instrumenting my
> code, not really by running the code through a real JUnit plugin, like the
> surefire maven plugin.
>
> I also initially said that it would take some time because a more important
> refactoring was necessary. Indeed, I realized that the JUnitRunner was more
> or less always forcing the sequential execution of specs.
>
> The net result of all this is that:
>
>  * I refactored the JUnitRunner
>  * the timings should display properly now (I tested it with Maven)
>  * the specifications can now run concurrently (so you should see improved
> times if you don't include the "sequential" argument)
>
> I pushed a new 1.12-SNAPSHOT with all this, thanks for confirming that the
> situation is indeed better.

I still get the wrong results, see below. Is there a way to verify the
changes have been pushed to sonatype?

It also seems that even with "args(sequential=true)" the tests run
concurrently, at least in eclipse.

Not sure where to look next. Could of course be an issue in gradle & eclipse :-)

/Jeppe


Eclipse timings:
0.1s
6s
6s

Gradle junit output:

<?xml version="1.0" encoding="UTF-8"?>
<testsuite errors="0" failures="0" hostname="jnmmbp.local"

name="fleetzone.unittest.SerializersSpec" tests="6" time="0.124"
timestamp="2012-06-14T12:06:09">

<properties />
<ignored-testcase classname="fleetzone.unittest.SerializersSpec"
name="CaseObjectSerializer should::correctly write/read case class
containing case objects" time="0.0" />
<testcase classname="fleetzone.unittest.SerializersSpec"
name="CaseObjectSerializer should::correctly write/read case class

containing case objects" time="0.0010" />

<ignored-testcase classname="fleetzone.unittest.SerializersSpec"
name="CaseObjectSerializer should::wait 3 secs" time="0.0" />
<testcase classname="fleetzone.unittest.SerializersSpec"

name="CaseObjectSerializer should::wait 3 secs" time="0.0010" />

<ignored-testcase classname="fleetzone.unittest.SerializersSpec"
name="CaseObjectSerializer should::wait 6 secs" time="0.0" />
<testcase classname="fleetzone.unittest.SerializersSpec"
name="CaseObjectSerializer should::wait 6 secs" time="0.0" />
<system-out><![CDATA[]]></system-out>
<system-err><![CDATA[]]></system-err>
</testsuite>

Gradle

[etorreborre]

Sorry about that Jeppe.

It is possible that the Gradle JUnit plugin handles things a bit differently than the Surefire plugin in Maven.

I'm going to download Gradle and try to reproduce your situation (bear with me because I've never used Gradle before).

I will update you later on that.

E.

[Jeppe Nejsum Madsen]

On Thu, Jun 14, 2012 at 3:34 PM, etorreborre <etorr...@gmail.com> wrote:
> Sorry about that Jeppe.
>
> It is possible that the Gradle JUnit plugin handles things a bit differently
> than the Surefire plugin in Maven.
>
> I'm going to download Gradle and try to reproduce your situation (bear with
> me because I've never used Gradle before).
>
> I will update you later on that.

I can create a small sample project and put it on github?

/Jeppe

[etorreborre]

I did some testing now with Gradle 1.0 (not bad as a build tool, a bit slow maybe) and I get good results.

I confirm that there was an issue with the sequential argument (sequential <=> args(sequential=true) btw) which was not used.

I published a fix so that this argument can be used but the Gradle JUnit infrastructure doesn't like when I write to the console concurrently:

 <failure message="org.gradle.listener.ListenerNotificationException: Failed to notify test result processor." type="org.gradle.listener.ListenerNotificationException">org.gradle.listener.ListenerNotificationException: Failed to notify test result processor.

at org.gradle.messaging.dispatch.BroadcastDispatch.dispatch(BroadcastDispatch.java:97)

at org.gradle.messaging.dispatch.BroadcastDispatch.dispatch(BroadcastDispatch.java:32)

at org.gradle.messaging.dispatch.ProxyDispatchAdapter$DispatchingInvocationHandler.invoke(ProxyDispatchAdapter.java:93)

at $Proxy3.output(Unknown Source)

at org.gradle.api.internal.tasks.testing.processors.CaptureTestOutputTestResultProcessor$StdOutForwarder.onOutput(CaptureTestOutputTestResultProcessor.java:90)

at org.gradle.logging.internal.DefaultStandardOutputRedirector$WriteAction.execute(DefaultStandardOutputRedirector.java:83)

at org.gradle.logging.internal.DefaultStandardOutputRedirector$WriteAction.execute(DefaultStandardOutputRedirector.java:79)

at org.gradle.util.LineBufferingOutputStream$StringOutput.write(LineBufferingOutputStream.java:148)

at org.gradle.util.LineBufferingOutputStream.flush(LineBufferingOutputStream.java:121)

at org.gradle.util.LineBufferingOutputStream.write(LineBufferingOutputStream.java:93)

at sun.nio.cs.StreamEncoder.writeBytes(StreamEncoder.java:221)

at sun.nio.cs.StreamEncoder.implFlushBuffer(StreamEncoder.java:291)

at sun.nio.cs.StreamEncoder.flushBuffer(StreamEncoder.java:104)

at org.gradle.util.LinePerThreadBufferingOutputStream.println(LinePerThreadBufferingOutputStream.java:200)

at examples.TestSpec$$anonfun$1$$anonfun$apply$1.apply(TestSpec.scala:11)

at examples.TestSpec$$anonfun$1$$anonfun$apply$1.apply(TestSpec.scala:8)

Caused by: java.lang.ArrayIndexOutOfBoundsException

at org.gradle.api.internal.tasks.testing.junit.JUnitXmlReportGenerator.output(JUnitXmlReportGenerator.java:61)

at org.gradle.api.internal.tasks.testing.results.StateTrackingTestResultProcessor.output(StateTrackingTestResultProcessor.java:79)

at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)

at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57)

at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)

at org.gradle.messaging.dispatch.ReflectionDispatch.dispatch(ReflectionDispatch.java:35)

at org.gradle.messaging.dispatch.ReflectionDispatch.dispatch(ReflectionDispatch.java:24)

at org.gradle.messaging.dispatch.BroadcastDispatch.dispatch(BroadcastDispatch.java:88)

I've republished 1.12-SNAPSHOT for all Scala versions >= 2.9.1 <= 2.9.2 so if you look at the dates on Sonatype you should indeed get the proper one.

Eric.

[etorreborre]

Yes please if the latest SNAPSHOT doesn't work for you.

[Jeppe Nejsum Madsen]

On Thu, Jun 14, 2012 at 5:21 PM, etorreborre <etorr...@gmail.com> wrote:
[...

> I've republished 1.12-SNAPSHOT for all Scala versions >= 2.9.1 <= 2.9.2 so
> if you look at the dates on Sonatype you should indeed get the proper one.

Thanks. I've wiped the dependency cache, re-downloaded and everything
seems to work now!

Now onto making the tests faster ;-)

/Jeppe

[etorreborre]

Good to know!