Disasterous JUnit behaviour

In the spirit of Hani's distaste for the latest builds, I too am upset by the terrible performance of the JUnit support. I have a test case, entire code as follows:

public class TestAdd extends TestCase {
public void testAdd() {
assertEquals(4, 2 + 2);
}
}

When running TestAdd, the following command line program is run:

C:/j2sdk1.4.2\bin\java -Dfile.encoding=windows-1252 -classpath -Didea.launcher.port=7532 -Didea.launcher.library=C:\IntelliJ-IDEA-4.0-1131\bin\breakgen.dll com.intellij.rt.execution.application.AppMain com.intellij.rt.execution.junit2.JUnitStarter -ideVersion5 com.spokesoftware.data.TestAdd

Then we wait up to 10 seconds (7 on average) and then finally the green bar comes up.

I decided to run this from the command line and noticed it was slow there as well. So then I decided to do some thread dumps:

=========================================================

Full thread dump Java HotSpot(TM) Client VM (1.4.2-b28 mixed mode):

"Signal Dispatcher" daemon prio=10 tid=0x009fc098 nid=0xd08 waiting on condition


"Finalizer" daemon prio=9 tid=0x009bd478 nid=0xd28 in Object.wait() [2b5f000..2b
5fd94]
at java.lang.Object.wait(Native Method)
- waiting on (a java.lang.ref.ReferenceQueue$Lock) at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:111) - locked <0x10010498> (a java.lang.ref.ReferenceQueue$Lock) at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:127) at java.lang.ref.Finalizer$FinalizerThread.run(Finalizer.java:159) "Reference Handler" daemon prio=10 tid=0x009bc048 nid=0xae8 in Object.wait() [2b 1f000..2b1fd94] at java.lang.Object.wait(Native Method) - waiting on <0x10010388> (a java.lang.ref.Reference$Lock) at java.lang.Object.wait(Object.java:429) at java.lang.ref.Reference$ReferenceHandler.run(Reference.java:115) - locked <0x10010388>]]> (a java.lang.ref.Reference$Lock)

"main" prio=5 tid=0x00037bf0 nid=0x8f4 runnable
at java.util.zip.ZipFile.open(Native Method)
at java.util.zip.ZipFile.(ZipFile.java:112) at java.util.jar.JarFile.(JarFile.java:127) at java.util.jar.JarFile.(JarFile.java:65) at sun.misc.URLClassPath$JarLoader.getJarFile(URLClassPath.java:575) at sun.misc.URLClassPath$JarLoader.(URLClassPath.java:542) at sun.misc.URLClassPath$3.run(URLClassPath.java:320) at java.security.AccessController.doPrivileged(Native Method) at sun.misc.URLClassPath.getLoader(URLClassPath.java:309) at sun.misc.URLClassPath.getLoader(URLClassPath.java:286) - locked <0x1003d2f8> (a sun.misc.URLClassPath) at sun.misc.URLClassPath.getResource(URLClassPath.java:156) at java.net.URLClassLoader$1.run(URLClassLoader.java:191) at java.security.AccessController.doPrivileged(Native Method) at java.net.URLClassLoader.findClass(URLClassLoader.java:187) at java.lang.ClassLoader.loadClass(ClassLoader.java:289) - locked <0x1003d038> (a sun.misc.Launcher$AppClassLoader) at sun.misc.Launcher$AppClassLoader.loadClass(Launcher.java:274) - locked <0x1003d038> (a sun.misc.Launcher$AppClassLoader) at java.lang.ClassLoader.loadClass(ClassLoader.java:235) at java.lang.ClassLoader.loadClassInternal(ClassLoader.java:302) - locked <0x1003d038>]]> (a sun.misc.Launcher$AppClassLoader)

"VM Thread" prio=5 tid=0x009fb6f8 nid=0x8cc runnable

"VM Periodic Task Thread" prio=10 tid=0x009fe890 nid=0xd84 waiting on condition

"Suspend Checker Thread" prio=10 tid=0x009bfb80 nid=0xfd4 runnable

=========================================================

I dumped threads about half a second later and got:

Full thread dump Java HotSpot(TM) Client VM (1.4.2-b28 mixed mode):

=========================================================

"Signal Dispatcher" daemon prio=10 tid=0x009fc098 nid=0xd08 waiting on condition


"Finalizer" daemon prio=9 tid=0x009bd478 nid=0xd28 in Object.wait() [2b5f000..2b
5fd94]
at java.lang.Object.wait(Native Method)
- waiting on (a java.lang.ref.ReferenceQueue$Lock) at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:111) - locked <0x10010498> (a java.lang.ref.ReferenceQueue$Lock) at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:127) at java.lang.ref.Finalizer$FinalizerThread.run(Finalizer.java:159) "Reference Handler" daemon prio=10 tid=0x009bc048 nid=0xae8 in Object.wait() [2b 1f000..2b1fd94] at java.lang.Object.wait(Native Method) - waiting on <0x10010388> (a java.lang.ref.Reference$Lock) at java.lang.Object.wait(Object.java:429) at java.lang.ref.Reference$ReferenceHandler.run(Reference.java:115) - locked <0x10010388>]]> (a java.lang.ref.Reference$Lock)

"main" prio=5 tid=0x00037bf0 nid=0x8f4 runnable
at java.util.zip.ZipFile.open(Native Method)
at java.util.zip.ZipFile.(ZipFile.java:112) at java.util.jar.JarFile.(JarFile.java:127) at java.util.jar.JarFile.(JarFile.java:65) at sun.misc.URLClassPath$JarLoader.getJarFile(URLClassPath.java:575) at sun.misc.URLClassPath$JarLoader.(URLClassPath.java:542) at sun.misc.URLClassPath$3.run(URLClassPath.java:320) at java.security.AccessController.doPrivileged(Native Method) at sun.misc.URLClassPath.getLoader(URLClassPath.java:309) at sun.misc.URLClassPath.getLoader(URLClassPath.java:286) - locked <0x1003d2f8> (a sun.misc.URLClassPath) at sun.misc.URLClassPath.getResource(URLClassPath.java:156) at java.net.URLClassLoader$1.run(URLClassLoader.java:191) at java.security.AccessController.doPrivileged(Native Method) at java.net.URLClassLoader.findClass(URLClassLoader.java:187) at java.lang.ClassLoader.loadClass(ClassLoader.java:289) - locked <0x1003d038> (a sun.misc.Launcher$AppClassLoader) at sun.misc.Launcher$AppClassLoader.loadClass(Launcher.java:274) - locked <0x1003d038> (a sun.misc.Launcher$AppClassLoader) at java.lang.ClassLoader.loadClass(ClassLoader.java:235) at java.lang.ClassLoader.loadClassInternal(ClassLoader.java:302) - locked <0x1003d038>]]> (a sun.misc.Launcher$AppClassLoader)

"VM Thread" prio=5 tid=0x009fb6f8 nid=0x8cc runnable

"VM Periodic Task Thread" prio=10 tid=0x009fe890 nid=0xd84 waiting on condition

"Suspend Checker Thread" prio=10 tid=0x009bfb80 nid=0xfd4 runnable

=========================================================

This confirmed my fear: something is waiting on a jar. I believe that this is also causing the crappy "wait" behavior I see when doing builds (anyone else see the dreaded "Make - messages" screen with no messages sit around for up to 10 seconds?)

Please fix this!

Patrick

2 comments

Oh, and just so we're all on the same page -- when I run this command line not a single java.exe process is running, so there isn't a chance of another java process (IDEA, app server, etc) locking on to the jar

0

On 2004/02/02 21:40, Pat Lightbody wrote:

Then we wait up to 10 seconds (7 on average) and then finally the
green bar comes up.


On my machine the "instantiating tests..." message counts just one
second and the test itself doesn't take any time at all. In older builds
starting tests did sometimes take a very long time, but they fixed it
for me...


Bas

0

Please sign in to leave a comment.