Poor performance in jUnit tests

[Vitaly_Litvak]

Hi

We are moving from ant build script to gradle. Everything looked good until we came to running our jUnit integration tests. In nightly run it takes about 2 hours (via ant), but running same tests with gradle takes about 5 hours. This is very strange. From brief investigation I have found that there is some correlation with the number of methods within test class. The bigger is the number the slower is test. Now I am running a single test class with 28 test methods. Running either from ant or from eclipse or from intellij idea takes 1 minute, while running same test from gradle takes 3 minute and 30 seconds. I tried using both 1.8 and 1.9 gradle.

The test task:

task testSingle(type: Test) {

classpath = configurations.coreTest

maxHeapSize = ‘1G’

jvmArgs ‘-XX:MaxPermSize=192M’

include ‘com/test/core/CAllocateGainTest*’

}

Please see screen shots

• Running test with gradle

Memory usage

• Gradle process

• Forked gradle worker with jUnit test

• Running same test in eclipse

Eclipse settings

UPDATE

When I use ant’s junit task with similar configuration (see snippet below) test runs just fine:

task testAllocateGains() {

ant.junit(fork: ‘yes’, maxmemory: ‘1G’) {

formatter(type: ‘xml’)

classpath(path: configurations.coreTest.asPath)

jvmarg(value: ‘-XX:MaxPermSize=129M’)

batchtest(todir: ‘build/test-results’) {

fileset(dir: ‘build/classes/test’) {

include (name: ‘com/test/core/CAllocateGainTest*’)

}

}

}

}

Console output:

$ gradle testAllocateGains

:testAllocateGains UP-TO-DATE

BUILD SUCCESSFUL

Total time: 1 mins 15.575 secs

Memory usage

• Gradle process

• Forked ant jUnit process

Does anyone have any idea on how can I profile this issue?

[luke_daley]

Are these tests writing much to stdout?

Any interesting JUnit config like custom runners?

[Vitaly_Litvak]

Thanks for your reply.

Are these tests writing much to stdout?

No, not that much. Actually they were writing and I thought this was the case. When I’ve reduced output volume couple of times (~2.5) the total test execution time almost didn’t change. Tomorrow I will try disabling output at all (via log4j configuration) if this could be the case.

Any interesting JUnit config like custom runners?

Nope. Just classes with methods using standard jUnit annotations. The test case from post body (with measurements) is just a class, which is derived from some AbstractTest containing common initialization methods (bring up hibernate session factory, etc.) annotated by @BeforeClass and tear down methods annotated by @AfterClass.

[Vitaly_Litvak]

FIY we are still trying to work out these performance issues because gradle satisfy our needs in all other aspects. We tried disabling logging without any success (only little performance gain). Then we have written a synthetic test, with following code:

for (int i = 0; i < 1024 * 20; i++) {

CLogger.info(“iteration #” + i);

}

Then copied and pasted it into 32 test methods. It is working two times slower then from ant. After playing around we have found that the reason is our way of finding appropriate logger:

// clogger.getinstance()

try {

String invokingClass = getInvokingClass(Thread.currentThread().getStackTrace());

return Logger.getLogger(invokingClass);

} catch (Exception e) {

return Logger.getRootLogger();

}

// getinvokingclass()

private static String getInvokingClass(StackTraceElement[] stackTrace) {

for (int i = 0; i < stackTrace.length; i++) {

StackTraceElement ste = stackTrace[i];

String className = ste.getClassName();

if (className.startsFrom(“com.mycompany.”) && !isLoggerClass(className)) {

return className;

}

}

return “”;

}

So for some reason this code runs MUCH slower in gradle forked process than in ant’s.

Can you give some explanation why is this happening?

P.S. I know that this is not the best solution. We can change it, but the thing is that even after hard coding the ‘clogger.getInstance()’ method the non-synthetic (i.e. real) test does run with almost same poor performance.

[luke_daley]

Interesting.

First thought is that the stack will be deeper in Gradle as there is more infrastructure, so if that for loop exhausts the stack often that will be slower.

Your last paragraph seems to indicate that while this is slower with Gradle, it’s not the real culprit of the slow down. Do I understand correctly?

[Vitaly_Litvak]

1. Yes, but I guess it’s not the case because “com.mycompany.” package often (and in synthetic test too) as the second element of stack trace

2. That’s correct.

[luke_daley]

Hi Vitaly, sorry for the long absence of reply.

I still can’t work out what this would be.

Is there any chance you could provide a reproducible sample? That way I can load it up and look into it.

[Vitaly_Litvak]

Hi

I will try providing you an example when I come back to my work from vacation at the end of this week.

FIY We’ve ended up running our tests via junit ant task from gradle. This way it runs with similar overall performance as it was when we were using ant.

[luke_daley]

Many thanks. I’m pretty keen to resolve this issue, but I really need that sample to do so.

Enjoy your vacation.

[Vitaly_Litvak]

Hi

First of all I want to make excuse about long delay in response.

We were working on this issue on our side and wished to send you the profiling results recorded using new awesome Flight Recorder tool bundled since jdk 7 update 40. But before this we investigated the profiling results on our side and found the root cause of issue. It is an issue in our code and gradle’s fault is only in a longer stack traces. Below are two problematic methods in our code:

1. Logging code that I have already posted above

// clogger.getinstance()

try {

String invokingClass = getInvokingClass(Thread.currentThread().getStackTrace());

return Logger.getLogger(invokingClass);

} catch (Exception e) {

return Logger.getRootLogger();

}

// getinvokingclass()

private static String getInvokingClass(StackTraceElement[] stackTrace) {

for (int i = 0; i < stackTrace.length; i++) {

StackTraceElement ste = stackTrace[i];

String className = ste.getClassName();

if (className.startsFrom(“com.mycompany.”) && !isLoggerClass(className)) {

return className;

}

}

return “”;

}

2. User friendly stack trace point

String getUserFriendlyStackPoint(Class<?>… classes) {

for(Class<?> cls : classes) {

for(StackTraceElement steX : Thread.currentThread().getStackTrace()) {

if (steX.getMethodName().equals(“getUserFriendlyStackPoint”)) {

continue;

}

try {

Class<?> stkCls = Class.forName(steX.getClassName());

Class<?> stkDeclCls = stkCls.getDeclaringClass();

if (cls.isAssignableFrom(stkCls) || stkDeclCls != null && cls.isAssignableFrom(stkDeclCls)) {

return “{” + Thread.currentThread().getName() + “}” + stkCls.getSimpleName() + “.” + steX.getMethodName() + “():” + steX.getLineNumber();

}

} catch (ClassNotFoundException e) {

continue;

}

}

}

return DTOUtility._getStackTrace().get(1);

}

Both of these methods highly depend on the “length” of stack trace, which is much bigger when running from gradle test worker. We use both of these methods quite often, which results in a large number of garbage collections (for this single test it generates 78 gigabytes of garbage) and thus in a poor performance.

Anyway, thanks for your help, you are doing awesome product

Wish you happy new year and happy holidays.

Best regards, Vitaly Litvak