Re : Re : Re : Running instrumented JUnit tests is much slower

View: New views

2 Messages — Rating Filter: Alert me

Re : Re : Re : Running instrumented JUnit tests is much slower

by Julien HENRY :: Rate this Message:

Reply to Author | View Threaded | Show Only this Message

I tried to monitor/profile test execution but it is a bit tricky as the JVM is forked.

I manage to have the following informations (see attached chart). SocketInputStream and TCPTransport are probably used by the debug chanel. But java.util.concurrent.locks.LockSupport.parkNanos may confirm your supposition about synchronized HashMap.

>
>De : Jake Cobb <jake.cobb@...>
>À : Julien HENRY <henryju@...>
>Envoyé le : Ven 23 Octobre 2009, 20 h 28 min 47 s
>Objet : Re: Re : Re : [Cobertura-devel] Running instrumented JUnit tests is much slower
>
>Julien,
>
>
>On Fri, Oct 23, 2009 at 1:57 PM, Julien HENRY <henryju@...> wrote:
>
>>I heard that one difference between Emma and Cobertura is that cobertura is counting the number of times each code line is executed wheras Emma is only telling if the line was executed or not (boolean). Could it be possible that because the tested algorithms contains big loops, the number of time a line is executed become very big and make a big
>> overhead?
>>
>
>Yes, that's possible although I'm still surprised by the magnitude. Cobertura increments counters for line coverage and for branches (including switch statements). The counters are long so that makes them more expensive to increment than int and certainly more than flipping a boolean. You are basically getting this inserted where it needs to count:
>
>ProjectData.getGlobalProjectData().getOrCreateClassData("CLASSNAME_HERE").touch(LINE_NUM_HERE);
>
>where getOrCreateClassData is synchronized and does a lookup on a synchronized HashMap.
>
>I suppose if Emma is only using booleans then it could get away with not using any synchronization since it will only ever turn a flag on and doesn't have to worry about inconsistent read/writes.
>
>That being said, those numbers still sound too high to just be the difference in instrumentation methodology, although I can't otherwise explain them.
>>
>
>>Another idea: we are using some introspection. Is it possible there is a problem with instrumented bytecode?
>>
>>
>
>If you mean normal reflection, this shouldn't be a problem. If you are doing something at the bytecode level, then perhaps. For example, AspectJ and Cobertura have known issues working together, although that results in incorrect coverage and not a performance problem as far as I know.
>
>-Jake
>
>
>

------------------------------------------------------------------------------
Come build with us! The BlackBerry(R) Developer Conference in SF, CA
is the only developer event you need to attend this year. Jumpstart your
developing skills, take BlackBerry mobile applications to market and stay
ahead of the curve. Join us from November 9 - 12, 2009. Register now!
http://p.sf.net/sfu/devconference
_______________________________________________
Cobertura-devel mailing list
Cobertura-devel@...
https://lists.sourceforge.net/lists/listinfo/cobertura-devel

cobertura.png (48K) Download Attachment

Re : Re : Re : Running instrumented JUnit tests is much slower

by Julien HENRY :: Rate this Message:

Reply to Author | View Threaded | Show Only this Message

Jake,

I have looked at the code and saw it is full of lock(). It seems to be a serious performance issue and certainly a big part of the overhead.

I know some lock are necessary to be thread safe, but look at the change:

(remind of my test case)

I wrote this simple class that will be instrumented:

public class App {
public void testCobertura() {
for (long i = 0; i < 1E+9; i++ ) {
}
}
}

and the associated JUnit test:
public class AppTest extends TestCase {
public void testApp() {
App app = new App();
app.testCobertura();
}
}

Running mvn clean test (no instrumentation)

1) with i < 1E+8 takes 0.165 sec

2) with i < 1E+9 takes 1.38 sec

Running mvn clean cobertura:cobertura (with instrumentation)

1) with i < 1E+8 takes 19 sec

2) with i < 1E+9 takes 196 sec

Now with modified cobertura sources (I have removed all lock() from ProjectData, ClassData, LineData, ...):

1) with i < 1E+8 takes 6.6 sec

2) with i < 1E+9 takes 65 sec

For a comparison here is the mvn clean emma:emma results:

1) with i < 1E+8 takes 0.241 sec

2) with i < 1E+9 takes 1.46 sec

There is still a big overhead (and we certainly loose thread safety) but I hope it shows there is something that have to be done concerning synchronization.

Regards,

Julien

----- Message d'origine ----

> De : Julien HENRY <henryju@...>
> À : Jake Cobb <jake.cobb@...>
> Cc : cobertura-devel@...
> Envoyé le : Ven 23 Octobre 2009, 22 h 28 min 54 s
> Objet : [Cobertura-devel] Re : Re : Re : Running instrumented JUnit tests is much slower
>
> I tried to monitor/profile test execution but it is a bit tricky as the JVM is
> forked.
>
> I manage to have the following informations (see attached chart).
> SocketInputStream and TCPTransport are probably used by the debug chanel. But
> java.util.concurrent.locks.LockSupport.parkNanos may confirm your supposition
> about synchronized HashMap.
>
>
> >
> >De : Jake Cobb
> >À : Julien HENRY
> >Envoyé le : Ven 23 Octobre 2009, 20 h 28 min 47 s
> >Objet : Re: Re : Re : [Cobertura-devel] Running instrumented JUnit tests is
> much slower
> >
> >Julien,
> >
> >
> >On Fri, Oct 23, 2009 at 1:57 PM, Julien HENRY wrote:
> >
> >>I heard that one difference between Emma and Cobertura is that cobertura is
> counting the number of times each code line is executed wheras Emma is only
> telling if the line was executed or not (boolean). Could it be possible that
> because the tested algorithms contains big loops, the number of time a line is
> executed become very big and make a big
> >> overhead?
> >>
> >
> >Yes, that's possible although I'm still surprised by the magnitude. Cobertura
> increments counters for line coverage and for branches (including switch
> statements). The counters are long so that makes them more expensive to
> increment than int and certainly more than flipping a boolean. You are
> basically getting this inserted where it needs to count:
> >
> >ProjectData.getGlobalProjectData().getOrCreateClassData("CLASSNAME_HERE").touch(LINE_NUM_HERE);
> >
> >where getOrCreateClassData is synchronized and does a lookup on a synchronized
> HashMap.
> >
> >I suppose if Emma is only using booleans then it could get away with not using
> any synchronization since it will only ever turn a flag on and doesn't have to
> worry about inconsistent read/writes.
> >
> >That being said, those numbers still sound too high to just be the difference
> in instrumentation methodology, although I can't otherwise explain them.
> >>
> >
> >>Another idea: we are using some introspection. Is it possible there is a
> problem with instrumented bytecode?
> >>
> >>
> >
> >If you mean normal reflection, this shouldn't be a problem. If you are doing
> something at the bytecode level, then perhaps. For example, AspectJ and
> Cobertura have known issues working together, although that results in incorrect
> coverage and not a performance problem as far as I know.
> >
> >-Jake
> >
> >
> >