Clover reports wildly varying coverage percentages on two runs of the same test

[Philip Stoev]

I am trying to obtain a Clover 3.1.11 coverage report on a Java program that is built with mvn (multi-project), but then run outside of Maven.

Every time the program is run in the same way the coverage report shows entirely different coverage percentages. Some classes that were reported as 0% during the previous run are then reported to have 60% coverage. Other classes have it exactly the opposite.

I have tried all three flush policies and a sub-second flush interval to no avail. strace reports that the coverage data file is indeed written to periodically.

My maven configuration is as follows:

<plugin>
                                <groupId>com.atlassian.maven.plugins</groupId>
                                <artifactId>maven-clover2-plugin</artifactId>
                                <version>3.1.11</version>
                                <configuration>
                                        <singleCloverDatabase>true</singleCloverDatabase>
                                        <baseDir>target/clover</baseDir>
                                        <flushpolicy>interval</flushpolicy>
                                        <flushinterval>500</flushinterval>
                                </configuration>
                        </plugin>

                                <dependency>
                                        <groupId>com.cenqua.clover</groupId>
                                        <artifactId>clover</artifactId>
                                        <version>3.1.11</version>
                                </dependency>

The sequence of steps that I use is as follows:

$ mvn clean clover2:clean compile clover2:setup install -DskipTests=true
... call produced .jar file outside of maven
$ mvn clover2:clover -DskipTests=true

Any help would be much appreciated. Thank you.

[jjaroczynski · Accepted solution]

Hi Philip,

I can see that you run:

mvn clean clover2:clean compile clover2:setup install

Please move clover2:setup before compile and try once again:

mvn clean clover2:clean clover2:setup compile install

Let us know the outcome.

Cheers,
Jacek

[Philip Stoev]

Yes, switching the phases as you describe resulted in repeatable coverage reports. Thank you very much for your help.

[Philip Stoev]

I have uploaded the requested files to https://support.atlassian.com/browse/CLV-5973

[Philip Stoev]

Hello,

To answer your questions:

#1. Yes a project rebuild is done before each attempt. I believe exactly the same code is used. The size of the clover.db file is exactly the same after each rebuild, though the size of the clover.db{hash} files is different after each rebuild even if exactly the same test is run. If multiple tests are made after the rebuild, they will all result in same-sized files.

For example, I rebuild the project and then I exercise just the --help function of my .jar file. This produces hash files of say 100 bytes every time I run the jar file. However, if I rebuild, future executions will now produce coverage files of 200 bytes until the next rebuild.

#2. I have changed my test to exit cleanly without having to kill the JVM, that is, I run a command-line option to the binary that causes it to exit immediately. And still, code coverage varies between runs. I have also performed experiments where the server is left to run for prolonged periods of time, the code coverage still fluctuated. To the best of my knowledge, no lazy initialization is used.

[Philip Stoev]

#3. The output from runing the jar file with -Dclover.logging.level=debug is:

Clover.getRecorder(/home/philips/git/nuodb/target/clover/clover.db, 1369142326765, 8589935092, 42590, [InstrumentationProperties={clover.distributed.coverage=null}, cloverSystemProperties={clover.logging.level=debug}]) resulting in new recorder called from (first 10 stack elements):
com_cenqua_clover.Clover$InitialisedRuntime$1.run(Clover.java:489)
com_cenqua_clover.Clover$InitialisedRuntime$1.run(Clover.java:477)
java.security.AccessController.doPrivileged(Native Method)
com_cenqua_clover.Clover$InitialisedRuntime.getRecorder(Clover.java:476)
com_cenqua_clover.Clover.getRecorder(Clover.java:106)
com.nuodb.agent.NuoAgent$__CLR3_1_11wrewrehgz3zojs.<clinit>(NuoAgent.java:57)
com.nuodb.agent.NuoAgent$1.<init>(NuoAgent.java:78)
com.nuodb.agent.NuoAgent.<clinit>(NuoAgent.java:75)

[creating new recorder for /home/philips/git/nuodb/target/clover/clover.db_1369142326765_8589935092]
CLOVER: No profiles defined in instrumented classes. Using standard settings.
Failed to newly create the recording-is-live flag file at /home/philips/git/nuodb/target/clover/clover.db.liverec because the file already exists
Started active flush thread for registry at /home/philips/git/nuodb/target/clover/clover.db, interval= 500
Added shutdown hook for registry at /home/philips/git/nuodb/target/clover/clover.db
Started recorder for registry at "/home/philips/git/nuodb/target/clover/clover.db": FixedSizeCoverageRecorder[elements.length=54394]
CLOVER: No profiles defined in instrumented classes. Using standard settings.
Distributed coverage is disabled.'
[found existing recorder for /home/philips/git/nuodb/target/clover/clover.db_1369142326765_8589935092]

#4. Setting the debug flag during clover2:clover produces no additional log output or errors

#5. I tried this on two different flavors of Linux, two different OpenJDK versions. All filesystems used are local.

[Marek Parfianowicz]

1) Did you perform project rebuild between run#1 and run#2? In other words, does subsequent executions of exactly the same code produce different coverage results?

2) Does your server code has some kind of lazy initialization of it's classes, i.e. sth that might take longer than 2 seconds? Have you tried to send kill signal later than 2 seconds?

3) Please run the Java TCP server with -Dclover.logging.level=debug - do you see any error messages like: class not found exceptions, problems with writing coverage files etc?

4) Please run clover2:clover task with -Dclover.logging.level=debug - are there any message like ""Ignoring coverage recording XXXX because no FileInfo supports its coverage range" or "Failed to load coverage recording XXXX"

In case tips above won't help, do not hesitate to raise a support ticket at http://support.atlassian.com (in the "Clover Support" project) and attach build logs, pom, clover.db and coverage files. I'll be happy to investigate it.

[Marek Parfianowicz]

PS: what OS version do you have? is there any chance that coverage files are being written on a network drive?

[Philip Stoev]

Hello,

The test is automated -- it is a script that performs exactly the same actions each time. No application server is used.

The application is a Java TCP server. It is started (java -jar ...) so that it can perform initialization and start to listen on its TCP port, and then killed via kill after 2 seconds. It does not accept any actual connections or process any actual requests, and yet the reported coverage is vastly different each time. The differences are so big that I do not think they can be explained by timing issues in the code being coverage-d.

For example:

From run #1:

com.nuodb.agent (15.9%)

com.nuodb.agent.auth (5.3%)

com.nuodb.agent.db (0%)

com.nuodb.agent.event (15.7%)

com.nuodb.agent.net (0%)

com.nuodb.agent.plugin (15.6%)

com.nuodb.agent.service (5.3%)

-rw-rw-r--. 1 philips philips 3673401 May 21 14:32 clover.db

-rw-rw-r--. 1 philips philips 415 May 21 14:32 clover.dba5yz54_hgz06hzz

-rw-rw-r--. 1 philips philips 381 May 21 14:32 clover.dba5yz54_hgz06hzz.1

---

And then run #2:

com.nuodb.agent (16%)

com.nuodb.agent.auth (0.8%) <- this was 5.3% above

com.nuodb.agent.db (0%)

com.nuodb.agent.event (15.7%)

com.nuodb.agent.net (0%)

com.nuodb.agent.plugin (0%) <- this was 15.6%

com.nuodb.agent.service (1.4%)

com.nuodb.agent.util (11.7%)

com.nuodb.compliance (0%)

-rw-rw-r--. 1 philips philips 3673401 May 21 14:35 clover.db

-rw-rw-r--. 1 philips philips 386 May 21 14:35 clover.dbe1a4se_hgz0bbjp

-rw-rw-r--. 1 philips philips 386 May 21 14:35 clover.dbe1a4se_hgz0bbjp.1

-rw-rw-r--. 1 philips philips 301 May 21 14:35 clover.dbsk4k9u_hgz0bbgb

-rw-rw-r--. 1 philips philips 284 May 21 14:35 clover.dbsk4k9u_hgz0bbgb.1

Thank you.

[Marek Parfianowicz]

Every time the program is run in the same way

Could you elaborate, please? Do you run automated tests or manual ones? Do you deploy a jar to some application server? Do you see the same amount of global (clover.dbsome_hash) and per-test (clover.dbsome_longer_hash.s) coverage files?

[Philip Stoev]

java version "1.6.0_33"

Java(TM) SE Runtime Environment (build 1.6.0_33-b03)

Java HotSpot(TM) 64-Bit Server VM (build 20.8-b03, mixed mode)