pitest icon indicating copy to clipboard operation
pitest copied to clipboard

GC overhead limit exceeded

Open mgonzcast opened this issue 2 years ago • 39 comments

Hi,

I have several modules in a project and only (the biggest one) fails with GC overhead limit exceeded.

I have searched around and I can´t find how to fix this.

Originally I run this command (which works in the rest of modules):

mvn clean install org.pitest:pitest-maven:mutationCoverage -DtimeoutConstant=10000 -DoutputFormats=XML -DexportLineCoverage=true -DtimestampedReports=false

and I get:

[INFO] Defaulting target classes to match packages in build directory [INFO] Defaulting target tests to match packages in test build directory 11:38:57 PIT >> INFO : Verbose logging is disabled. If you encounter a problem, please enable it before reporting an issue. 11:39:04 PIT >> INFO : Incremental analysis reduced number of mutations by 0 11:39:04 PIT >> INFO : Created 668 mutation test units in pre scan 11:39:05 PIT >> INFO : Sending 861 test classes to minion 11:39:05 PIT >> INFO : Sent tests to minion \11:43:12 PIT >> INFO : MINION : log4j:ERROR A "org.apache.log4j.xml.DOMConfigurator" object is not assignable to a "org.apache.log4j.spi.Configurator" variable. 11:43:12 PIT >> INFO : MINION : log4j:ERROR The class "org.apache.log4j.spi.Configurator" was loaded by 11:43:12 PIT >> INFO : MINION : log4j:ERROR [org.powermock.core.classloader.javassist.JavassistMockClassLoader@1e313166] whereas object of type 11:43:12 PIT >> INFO : MINION : log4j:ERROR "org.apache.log4j.xml.DOMConfigurator" was loaded by [sun.misc.Launcher$AppClassLoader@18b4aac2]. 11:43:12 PIT >> INFO : MINION : log4j:ERROR Could not instantiate configurator [org.apache.log4j.xml.DOMConfigurator]. /11:59:21 PIT >> INFO : MINION : Java HotSpot(TM) 64-Bit Server VM warning: CodeCache is full. Compiler has been disabled. 11:59:21 PIT >> INFO : MINION : Java HotSpot(TM) 64-Bit Server VM warning: Try increasing the code cache size using -XX:ReservedCodeCacheSize= -

I have tried:

mvn clean install org.pitest:pitest-maven:mutationCoverage -DtimeoutConstant=10000 -DoutputFormats=XML -DexportLineCoverage=true -DtimestampedReports=false -DjvmArgs="-Xmx4096M,-XX:ReservedCodeCacheSize=2048M,-XX:-UseGCOverheadLimit" -Dthreads=4 " -Dfeatures="+CLASSLIMIT" -DwithHistory

But although the number of tests unit decreased, the number of test classes sent to minion are still 865 and I get an outofmemroy and GC overhead limit exceeded.

Any hint?

mgonzcast avatar Jun 15 '22 10:06 mgonzcast

The error looks to be occuring in the minion launched to gather block coverage, so gc parameters need to be passed to the child process. This can be done using pitest's jvmArgs property.

Unless this module is excessively large, it seems likely that there is some sort of memory leak in the tests when run via pitest. I can see powermock is in use, which is a likely culprit. What else is in use?

Also, CLASSLIMIT will reduce the number of mutations generated, but has no effect on the number of tests detected.

hcoles avatar Jun 15 '22 11:06 hcoles

-DjvmArgs="-Xmx4096M,-XX:ReservedCodeCacheSize=2048M,-XX:-UseGCOverheadLimit"

Thanks! As you can see I already use jvmArgs. Is there anything am I missing?

Unless this module is excessively large, it seems likely that there is some sort of memory leak in the tests when run via pitest. I can see powermock is in use, which is a likely culprit. What else is in use?

Junit tests. Is there anyway to narrow down which test(s) is(are) the culprit?

This is exactly the output of the error on the second command:

12:12:57 PIT >> INFO : Verbose logging is disabled. If you encounter a problem, please enable it before reporting an issue. 12:13:02 PIT >> INFO : Incremental analysis reduced number of mutations by 0 12:13:02 PIT >> INFO : Created 325 mutation test units in pre scan 12:13:03 PIT >> INFO : Sending 861 test classes to minion 12:13:04 PIT >> INFO : Sent tests to minion \12:17:24 PIT >> INFO : MINION : log4j:ERROR A "org.apache.log4j.xml.DOMConfigurator" object is not assignable to a "org.apache.log4j.spi.Configurator" variable. 12:17:24 PIT >> INFO : MINION : log4j:ERROR The class "org.apache.log4j.spi.Configurator" was loaded by 12:17:24 PIT >> INFO : MINION : log4j:ERROR [org.powermock.core.classloader.javassist.JavassistMockClassLoader@785f57d0] whereas object of type 12:17:24 PIT >> INFO : MINION : log4j:ERROR "org.apache.log4j.xml.DOMConfigurator" was loaded by [sun.misc.Launcher$AppClassLoader@18b4aac2]. 12:17:24 PIT >> INFO : MINION : log4j:ERROR Could not instantiate configurator [org.apache.log4j.xml.DOMConfigurator]. \12:43:39 PIT >> WARNING : Error while watching child process java.util.concurrent.ExecutionException: java.lang.OutOfMemoryError: GC overhead limit exceeded at java.util.concurrent.FutureTask.report(FutureTask.java:122) at java.util.concurrent.FutureTask.get(FutureTask.java:192) at org.pitest.util.CommunicationThread.waitToFinish(CommunicationThread.java:59) at org.pitest.coverage.execute.CoverageProcess.waitToDie(CoverageProcess.java:35) at org.pitest.coverage.execute.DefaultCoverageGenerator.gatherCoverageData(DefaultCoverageGenerator.java:138) at org.pitest.coverage.execute.DefaultCoverageGenerator.calculateCoverage(DefaultCoverageGenerator.java:90) at org.pitest.coverage.execute.DefaultCoverageGenerator.calculateCoverage(DefaultCoverageGenerator.java:52) at org.pitest.mutationtest.tooling.MutationCoverage.runAnalysis(MutationCoverage.java:149) at org.pitest.mutationtest.tooling.MutationCoverage.runReport(MutationCoverage.java:139) at org.pitest.mutationtest.tooling.EntryPoint.execute(EntryPoint.java:123) at org.pitest.mutationtest.tooling.EntryPoint.execute(EntryPoint.java:54) at org.pitest.maven.RunPitStrategy.execute(RunPitStrategy.java:35) at org.pitest.maven.AbstractPitMojo.analyse(AbstractPitMojo.java:489) at org.pitest.maven.AbstractPitMojo.execute(AbstractPitMojo.java:419) at org.apache.maven.plugin.DefaultBuildPluginManager.executeMojo(DefaultBuildPluginManager.java:137) at org.apache.maven.lifecycle.internal.MojoExecutor.execute(MojoExecutor.java:210) at org.apache.maven.lifecycle.internal.MojoExecutor.execute(MojoExecutor.java:156) at org.apache.maven.lifecycle.internal.MojoExecutor.execute(MojoExecutor.java:148) at org.apache.maven.lifecycle.internal.LifecycleModuleBuilder.buildProject(LifecycleModuleBuilder.java:117) at org.apache.maven.lifecycle.internal.LifecycleModuleBuilder.buildProject(LifecycleModuleBuilder.java:81) at org.apache.maven.lifecycle.internal.builder.singlethreaded.SingleThreadedBuilder.build(SingleThreadedBuilder.java:56) at org.apache.maven.lifecycle.internal.LifecycleStarter.execute(LifecycleStarter.java:128) at org.apache.maven.DefaultMaven.doExecute(DefaultMaven.java:305) at org.apache.maven.DefaultMaven.doExecute(DefaultMaven.java:192) at org.apache.maven.DefaultMaven.execute(DefaultMaven.java:105) at org.apache.maven.cli.MavenCli.execute(MavenCli.java:972) at org.apache.maven.cli.MavenCli.doMain(MavenCli.java:293) at org.apache.maven.cli.MavenCli.main(MavenCli.java:196) at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) at java.lang.reflect.Method.invoke(Method.java:498) at org.codehaus.plexus.classworlds.launcher.Launcher.launchEnhanced(Launcher.java:282) at org.codehaus.plexus.classworlds.launcher.Launcher.launch(Launcher.java:225) at org.codehaus.plexus.classworlds.launcher.Launcher.mainWithExitCode(Launcher.java:406) at org.codehaus.plexus.classworlds.launcher.Launcher.main(Launcher.java:347) Caused by: java.lang.OutOfMemoryError: GC overhead limit exceeded at java.util.zip.ZipCoder.toString(ZipCoder.java:49) at java.util.zip.ZipFile.getZipEntry(ZipFile.java:584) at java.util.zip.ZipFile.access$900(ZipFile.java:60) at java.util.zip.ZipFile$ZipEntryIterator.next(ZipFile.java:540) at java.util.zip.ZipFile$ZipEntryIterator.nextElement(ZipFile.java:515) at java.util.zip.ZipFile$ZipEntryIterator.nextElement(ZipFile.java:496) at org.pitest.classpath.ArchiveClassPathRoot.classNames(ArchiveClassPathRoot.java:91) at org.pitest.classpath.NameCachingRoot.classNames(NameCachingRoot.java:51) at org.pitest.classpath.NameCachingRoot.getData(NameCachingRoot.java:36) at org.pitest.classpath.CompoundClassPathRoot.getData(CompoundClassPathRoot.java:27) at org.pitest.classpath.ClassPath.getClassData(ClassPath.java:101) at org.pitest.classpath.ClassPathByteArraySource.getBytes(ClassPathByteArraySource.java:41) at org.pitest.classinfo.Repository.querySource(Repository.java:82) at org.pitest.classpath.CodeSource.fetchClassBytes(CodeSource.java:80) at org.pitest.classpath.CodeSource.getBytes(CodeSource.java:95) at org.pitest.coverage.analysis.LineMapper.mapLines(LineMapper.java:31) at org.pitest.coverage.LegacyClassCoverage.calculateLinesForBlocks(LegacyClassCoverage.java:135) at org.pitest.coverage.LegacyClassCoverage.getLinesForBlock(LegacyClassCoverage.java:124) at org.pitest.coverage.LegacyClassCoverage.addTestToClasses(LegacyClassCoverage.java:89) at org.pitest.coverage.CoverageData.calculateClassCoverage(CoverageData.java:66) at org.pitest.coverage.execute.DefaultCoverageGenerator$1.accept(DefaultCoverageGenerator.java:184) at org.pitest.coverage.execute.DefaultCoverageGenerator$1.accept(DefaultCoverageGenerator.java:176) at org.pitest.coverage.execute.Receive.handleTestEnd(Receive.java:76) at org.pitest.coverage.execute.Receive.apply(Receive.java:43) at org.pitest.util.SocketReadingCallable.receiveResults(SocketReadingCallable.java:56) at org.pitest.util.SocketReadingCallable.call(SocketReadingCallable.java:34) at org.pitest.util.SocketReadingCallable.call(SocketReadingCallable.java:11) at java.util.concurrent.FutureTask.run(FutureTask.java:266) at java.lang.Thread.run(Thread.java:748) 12:43:39 PIT >> SEVERE : Coverage generator Minion exited abnormally due to UNKNOWN_ERROR

mgonzcast avatar Jun 15 '22 11:06 mgonzcast

Thanks! As you can see I already use jvmArgs. Is there anything am I missing?

Sorry, I completely misread the command line. That looks correct to me for passing params to the minions, however, now we have the full stack trace, the GC overhead limit exceeded error looks to be being thrown in the main process.

So, working around this would require tweaking memory settings in both the minion and the main process.

Which still leaves the question of what is going on.

Either

  • I've managed to make the main process very memory inefficient with a recent change
  • One of the tests is causing much more coverage data to be sent then is normal
  • This module really is huge, and there's just a lot of data to deal with.

Turning on verbose logging might help identify a problematic test (I usually pipe the whole output to a file and wade through). Disabling any test that use powermock / anything the manipulates bytecode might also help narrow down the issue to a list of culprets.

A thread dump of the main process would also shed some light.

hcoles avatar Jun 15 '22 12:06 hcoles

So, working around this would require tweaking memory settings in both the minion and the main process.

How do I do that? Setting MAVEN_OPTS maybe? If I try to set up:

set MAVEN_OPTS="-Xmx1024M, -XX:ReservedCodeCacheSize=1024M,-XX:-UseGCOverheadLimit"

I get an error complaining about the heap size. I remove the -Xmx1024M flag I get an error regarding the reservedcochecachesize

Turning on verbose logging might help identify a problematic test (I usually pipe the whole output to a file and wade through). Disabling any test that use powermock / anything the manipulates bytecode might also help narrow down the issue to a list of culprets.

How do I disable any particular test? with excludedTestClasses?

A thread dump of the main process would also shed some light.

Which command do you recommend me for that?

mgonzcast avatar Jun 15 '22 13:06 mgonzcast

How do I do that? Setting MAVEN_OPTS maybe? If I try to set up:

set MAVEN_OPTS="-Xmx1024M, -XX:ReservedCodeCacheSize=1024M,-XX:-UseGCOverheadLimit"

I get an error complaining about the heap size. I remove the -Xmx1024M flag I get an error regarding the reservedcochecachesize

This is because of the commas. Try:

MAVEN_OPTS="-Xmx1024M -XX:ReservedCodeCacheSize=1024M -XX:-UseGCOverheadLimit"

Stephan202 avatar Jun 15 '22 13:06 Stephan202

This is because of the commas. Try:

MAVEN_OPTS="-Xmx1024M -XX:ReservedCodeCacheSize=1024M -XX:-UseGCOverheadLimit"

I still get

Invalid maximum heap size: -Xmx1024M -XX:ReservedCodeCacheSize=1024M -XX:-UseGCOverheadLimit Error: Could not create the Java Virtual Machine. Error: A fatal exception has occurred. Program will exit.

mgonzcast avatar Jun 15 '22 13:06 mgonzcast

Then I wonder whether there are any non-visible/non-space characters in there. For example, with both JDK 11 and 17 I get:

$ MAVEN_OPTS="-XmxFOO -XX:ReservedCodeCacheSize=1024M -XX:-UseGCOverheadLimit" mvn clean
Invalid maximum heap size: -XmxFOO
Error: Could not create the Java Virtual Machine.
Error: A fatal exception has occurred. Program will exit.

Observe how my error message says Invalid maximum heap size: -XmxFOO but does not include the rest of the string. This makes me believe that in your case the space after -Xmx1024M isn't a regular space, but e.g. a non-breaking space.

Stephan202 avatar Jun 15 '22 14:06 Stephan202

Many thanks, apparently on Windows you can´t use quotes with MAVEN_OPTS, so you have to use:

set MAVEN_OPTS=-Xmx1024M -XX:ReservedCodeCacheSize=1024M -XX:-UseGCOverheadLimit

without quotes

After excluding a powermock class it took more than 4 hours but no luck:

7:32:23 PIT >> INFO : Verbose logging is disabled. If you encounter a problem, please enable it before reporting an issue. 7:32:28 PIT >> INFO : Incremental analysis reduced number of mutations by 0 7:32:28 PIT >> INFO : Created 325 mutation test units in pre scan 7:32:29 PIT >> INFO : Sending 861 test classes to minion 7:32:30 PIT >> INFO : Sent tests to minion -12:01:32 PIT >> WARNING : Error while watching child process java.util.concurrent.ExecutionException: java.lang.OutOfMemoryError: Java heap space at java.util.concurrent.FutureTask.report(FutureTask.java:122) at java.util.concurrent.FutureTask.get(FutureTask.java:192) at org.pitest.util.CommunicationThread.waitToFinish(CommunicationThread.java:59) at org.pitest.coverage.execute.CoverageProcess.waitToDie(CoverageProcess.java:35) at org.pitest.coverage.execute.DefaultCoverageGenerator.gatherCoverageData(DefaultCoverageGenerator.java:138) at org.pitest.coverage.execute.DefaultCoverageGenerator.calculateCoverage(DefaultCoverageGenerator.java:90) at org.pitest.coverage.execute.DefaultCoverageGenerator.calculateCoverage(DefaultCoverageGenerator.java:52) at org.pitest.mutationtest.tooling.MutationCoverage.runAnalysis(MutationCoverage.java:149) at org.pitest.mutationtest.tooling.MutationCoverage.runReport(MutationCoverage.java:139) at org.pitest.mutationtest.tooling.EntryPoint.execute(EntryPoint.java:123) at org.pitest.mutationtest.tooling.EntryPoint.execute(EntryPoint.java:54) at org.pitest.maven.RunPitStrategy.execute(RunPitStrategy.java:35) at org.pitest.maven.AbstractPitMojo.analyse(AbstractPitMojo.java:489) at org.pitest.maven.AbstractPitMojo.execute(AbstractPitMojo.java:419) at org.apache.maven.plugin.DefaultBuildPluginManager.executeMojo(DefaultBuildPluginManager.java:137) at org.apache.maven.lifecycle.internal.MojoExecutor.execute(MojoExecutor.java:210) at org.apache.maven.lifecycle.internal.MojoExecutor.execute(MojoExecutor.java:156) at org.apache.maven.lifecycle.internal.MojoExecutor.execute(MojoExecutor.java:148) at org.apache.maven.lifecycle.internal.LifecycleModuleBuilder.buildProject(LifecycleModuleBuilder.java:117) at org.apache.maven.lifecycle.internal.LifecycleModuleBuilder.buildProject(LifecycleModuleBuilder.java:81) at org.apache.maven.lifecycle.internal.builder.singlethreaded.SingleThreadedBuilder.build(SingleThreadedBuilder.java:56) at org.apache.maven.lifecycle.internal.LifecycleStarter.execute(LifecycleStarter.java:128) at org.apache.maven.DefaultMaven.doExecute(DefaultMaven.java:305) at org.apache.maven.DefaultMaven.doExecute(DefaultMaven.java:192) at org.apache.maven.DefaultMaven.execute(DefaultMaven.java:105) at org.apache.maven.cli.MavenCli.execute(MavenCli.java:972) at org.apache.maven.cli.MavenCli.doMain(MavenCli.java:293) at org.apache.maven.cli.MavenCli.main(MavenCli.java:196) at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) at java.lang.reflect.Method.invoke(Method.java:498) at org.codehaus.plexus.classworlds.launcher.Launcher.launchEnhanced(Launcher.java:282) at org.codehaus.plexus.classworlds.launcher.Launcher.launch(Launcher.java:225) at org.codehaus.plexus.classworlds.launcher.Launcher.mainWithExitCode(Launcher.java:406) at org.codehaus.plexus.classworlds.launcher.Launcher.main(Launcher.java:347) Caused by: java.lang.OutOfMemoryError: Java heap space at java.util.TreeSet.<init>(TreeSet.java:141) at org.pitest.coverage.CoverageData.addTestsToBlockMap(CoverageData.java:123) at org.pitest.coverage.CoverageData.calculateClassCoverage(CoverageData.java:71) at org.pitest.coverage.execute.DefaultCoverageGenerator$1.accept(DefaultCoverageGenerator.java:184) at org.pitest.coverage.execute.DefaultCoverageGenerator$1.accept(DefaultCoverageGenerator.java:176) at org.pitest.coverage.execute.Receive.handleTestEnd(Receive.java:76) at org.pitest.coverage.execute.Receive.apply(Receive.java:43) at org.pitest.util.SocketReadingCallable.receiveResults(SocketReadingCallable.java:56) at org.pitest.util.SocketReadingCallable.call(SocketReadingCallable.java:34) at org.pitest.util.SocketReadingCallable.call(SocketReadingCallable.java:11) at java.util.concurrent.FutureTask.run(FutureTask.java:266) at java.lang.Thread.run(Thread.java:748) 12:01:34 PIT >> SEVERE : Coverage generator Minion exited abnormally due to UNKNOWN_ERROR [INFO] ------------------------------------------------------------------------ [INFO] BUILD FAILURE [INFO] ------------------------------------------------------------------------ [INFO] Total time: 04:34 h [INFO] Finished at: 2022-06-16T12:01:34+02:00 [INFO] ------------------------------------------------------------------------

mgonzcast avatar Jun 16 '22 11:06 mgonzcast

I have to say I am using JDK 8 and Maven 3.8.4

mgonzcast avatar Jun 16 '22 11:06 mgonzcast

@mgonzcast Can you give an indication of how large this module is? How long do the tests take to run wihtout pitest? Roughly how many thousand lines of code is it?

hcoles avatar Jun 16 '22 11:06 hcoles

Thanks for being so responsive. The module has 17k lines of code and 1.6K of junit tests. I would say the tests take around 20-30 minutes to run.

mgonzcast avatar Jun 16 '22 11:06 mgonzcast

Do you have any pitest configuration in the pom?

hcoles avatar Jun 16 '22 11:06 hcoles

Do you have any pitest configuration in the pom?

No, nothing in pom about pitest. I have to say this is part of three module project but no pom has any reference about pitest. The other two modules are quite smaller (2.7k lines of code and 1.2k junit tests) and run pitest without any issue.

mgonzcast avatar Jun 16 '22 12:06 mgonzcast

I have checked and tests take around 7 minutes to run, sorry.

I am going to start excluding classes from pitest so I can narrow down where the issue is:

mvn clean install org.pitest:pitest-maven:mutationCoverage -DtimeoutConstant=10000 -DoutputFormats=XML -DexportLineCoverage=true -DtimestampedReports=false -DjvmArgs="-Xmx4096M,-XX:ReservedCodeCacheSize=2048M,-XX:-UseGCOverheadLimit" -Dthreads=4 -DexcludedClasses="my.company.group.bizz.*"

Do you think is the best way?

mgonzcast avatar Jun 16 '22 12:06 mgonzcast

You'll need to use excludedTestClasses, but yes, taking some educated guesses as to where the issue might be and excluded them seems like a good step forward.

hcoles avatar Jun 16 '22 12:06 hcoles

7 minutes to 4 hours is quite a leap. Generally the coverage system adds about 10% overhead. The slow down is almost certainly due to the excessive memory consumption.

hcoles avatar Jun 16 '22 12:06 hcoles

I think this issue has been previously reported here

https://github.com/hcoles/pitest/issues/841

Which is fortunate as I am able to replicate it using the assertj project as an input. The issue is not as severe, but memory consumption is much higher than I'd expect.

I've identified something in the coverage code which looks (on the face of it) to be incredibly stupid, and should significantly reduce memory consumption if fixed. I'm not sure if this is the actual root cause problem here, or just an exasperating factor.

hcoles avatar Jun 16 '22 14:06 hcoles

So, should I wait until you get the chance to look at it?

mgonzcast avatar Jun 16 '22 14:06 mgonzcast

@mgonzcast Anything you find would be useful, but unless repeatedly running a test suite is something that brings you great pleasure, you might want to wait until the fix that assertj has highlighted is confirmed + available.

hcoles avatar Jun 16 '22 14:06 hcoles

@mgonzcast Anything you find would be useful, but unless repeatedly running a test suite is something that brings you great pleasure, you might want to wait until the fix that assertj has highlighted is confirmed + available.

:) No great pleasure

I see the tests after your changes have worked. Let me know how I update pitest and if maybe the pitest sonarqube plugin has to be updated as well.

mgonzcast avatar Jun 16 '22 16:06 mgonzcast

It will likely be a little while before this is merged in. Changes to the coverage system have subtly degraded the performance of the overall mutation analysis on the past, so I'll need to do a bit of playing around to sanity check it.

Since it's a big change that affects the file pitest produces, it will go into a 1.9.0 release. I'll probably release the other queued changes as a 1.8.x release before then.

To play with it before then, you'll need to check out and build it. If you do a local install, the version number will be 1.0.0-SNAPSHOT.

hcoles avatar Jun 16 '22 16:06 hcoles

Since it's a big change that affects the file pitest produces, it will go into a 1.9.0 release. I'll probably release the other queued changes as a 1.8.x release before then.

When do you expect to release those changes? I can wait a couple of weeks.

To play with it before then, you'll need to check out and build it. If you do a local install, the version number will be 1.0.0-SNAPSHOT.

Not sure which parts do i have to rebuild and where to place them in my machine. Do I have to download code as it is now? Any instructions?

mgonzcast avatar Jun 17 '22 05:06 mgonzcast

@mgonzcast Should be released some time next week.

hcoles avatar Jun 17 '22 07:06 hcoles

@mgonzcast This is now released. 1.9.0 contains a fix for high memory consumption in the main process (it has no effect on the minions), and a change that greatly speedups up JUnit 5 tests during the coverage stage.

Since you look to have high memory consumption in the minions as well, I don't know how big the impact will be, but hopefully with things improved in the main process it will be easier to find any remaining issues.

hcoles avatar Jun 23 '22 10:06 hcoles

@hcoles Thanks. Today I tried the new release 1.9.0 with the following settings:

set MAVEN_OPTS=-Xmx1024M -XX:ReservedCodeCacheSize=1024M -XX:-UseGCOverheadLimit

mvn clean install org.pitest:pitest-maven:mutationCoverage -DtimeoutConstant=10000 -DoutputFormats=XML -DexportLineCoverage=true -DtimestampedReports=false -DjvmArgs="-Xmx4096M,-XX:ReservedCodeCacheSize=2048M,-XX:-UseGCOverheadLimit" -Dthreads=4  -DexcludedClasses="my.company.package1.*,my.company.package2.*" -Dfeatures="+CLASSLIMIT(limit[5])" -DwithHistory

And I get:

9:00:52 PIT >> INFO : Verbose logging is disabled. If you encounter a problem, please enable it before reporting an issue.
9:00:53 PIT >> INFO : Incremental analysis reduced number of mutations by 0
9:00:53 PIT >> INFO : Created  141 mutation test units in pre scan
9:00:55 PIT >> INFO : Sending 861 test classes to minion
9:00:55 PIT >> INFO : Sent tests to minion
/9:23:15 PIT >> INFO : MINION : Exception in thread "main" org.pitest.util.PitError: Software caused connection abort: socket write error
9:23:37 PIT >> INFO : MINION :
9:23:37 PIT >> INFO : MINION : Please copy and paste the information and the complete stacktrace below when reporting an issue
9:23:37 PIT >> INFO : MINION : VM : Java HotSpot(TM) 64-Bit Server VM
[INFO] ------------------------------------------------------------------------9:23:37 PIT >> INFO : MINION : Vendor : Oracle Corporation

9:23:37 PIT >> INFO : MINION : Version : 25.301-b09
9:23:37 PIT >> INFO : MINION : Uptime : 1326847
[INFO] BUILD FAILURE9:23:37 PIT >> INFO : MINION : Input ->

9:23:37 PIT >> INFO : MINION :  1 : -Djava.awt.headless=true
[INFO] ------------------------------------------------------------------------9:23:37 PIT >> INFO : MINION :  2 : -Xmx4096M

9:23:37 PIT >> INFO : MINION :  3 : -XX:ReservedCodeCacheSize=2048M
9:23:37 PIT >> INFO : MINION :  4 : -XX:-UseGCOverheadLimit
9:23:37 PIT >> INFO : MINION :  5 : -javaagent:C:\Users\myuser\AppData\Local\Temp\1656399652205054211747762176572642187201910552711.jar
9:23:37 PIT >> INFO : MINION :  6 : -Dclassworlds.conf=C:\Apache\apache-maven-3.8.4\bin\m2.conf
9:23:37 PIT >> INFO : MINION :  7 : -Dmaven.home=C:\Apache\apache-maven-3.8.4
9:23:37 PIT >> INFO : MINION :  8 : -Dlibrary.jansi.path=C:\Apache\apache-maven-3.8.4\lib\jansi-native
9:23:37 PIT >> INFO : MINION :  9 : -Dmaven.multiModuleProjectDirectory=C:\Users\myuser\code
9:23:37 PIT >> INFO : MINION : BootClassPathSupported : true
9:23:37 PIT >> INFO : MINION :
9:23:37 PIT >> INFO : MINION :  at org.pitest.util.Unchecked.translateCheckedException(Unchecked.java:20)
[INFO] Total time:  28:19 min9:23:37 PIT >> INFO : MINION :     at org.pitest.util.SafeDataOutputStream.writeByte(SafeDataOutputStream.java:85)

9:23:37 PIT >> INFO : MINION :  at org.pitest.coverage.execute.CoveragePipe.end(CoveragePipe.java:41)
9:23:37 PIT >> INFO : MINION :  at org.pitest.coverage.execute.CoverageMinion.main(CoverageMinion.java:109)
9:23:37 PIT >> INFO : MINION : Caused by: java.net.SocketException: Software caused connection abort: socket write error9:23:37 PIT >> INFO : MINION :  at java.net.SocketOutputStream.socketWrite0(Native Method)
[INFO] Finished at: 2022-06-28T09:23:37+02:009:23:37 PIT >> INFO : MINION :     at java.net.SocketOutputStream.socketWrite(SocketOutputStream.java:111)

9:23:37 PIT >> INFO : MINION :  at java.net.SocketOutputStream.write(SocketOutputStream.java:155)
[INFO] ------------------------------------------------------------------------9:23:37 PIT >> INFO : MINION :   at java.io.BufferedOutputStream.flushBuffer(BufferedOutputStream.java:82)

9:23:37 PIT >> INFO : MINION :  at java.io.BufferedOutputStream.write(BufferedOutputStream.java:95)
9:23:37 PIT >> INFO : MINION :  at java.io.DataOutputStream.writeByte(DataOutputStream.java:153)
9:23:37 PIT >> INFO : MINION :  at org.pitest.util.SafeDataOutputStream.writeByte(SafeDataOutputStream.java:83)
9:23:37 PIT >> INFO : MINION :  ... 2 more

mgonzcast avatar Jun 28 '22 09:06 mgonzcast

Thanks @mgonzcast, I assume this is for the large module?

Can you enable verbose logging and see if it provides any additional info?

hcoles avatar Jun 28 '22 14:06 hcoles

Thanks @mgonzcast, I assume this is for the large module?

Can you enable verbose logging and see if it provides any additional info?

Sure @hcoles. I enabled -X debug option and I get this in the logs:

------------------------------------------------------------------------
[INFO] BUILD FAILURE
[INFO] ------------------------------------------------------------------------
[INFO] Total time:  27:36 min
[INFO] Finished at: 2022-06-29T10:05:46+02:00
[INFO] ------------------------------------------------------------------------
[ERROR] Java heap space -> [Help 1]
java.lang.OutOfMemoryError: Java heap space
    at java.util.Arrays.copyOf (Arrays.java:3332)
    at java.lang.AbstractStringBuilder.ensureCapacityInternal (AbstractStringBuilder.java:124)
    at java.lang.AbstractStringBuilder.append (AbstractStringBuilder.java:448)
    at java.lang.StringBuffer.append (StringBuffer.java:270)
    at java.io.StringWriter.write (StringWriter.java:112)
    at java.io.PrintWriter.write (PrintWriter.java:456)
    at java.io.PrintWriter.write (PrintWriter.java:473)
    at java.io.PrintWriter.print (PrintWriter.java:603)
    at java.io.PrintWriter.println (PrintWriter.java:756)
    at java.lang.Throwable$WrappedPrintWriter.println (Throwable.java:765)
    at java.lang.Throwable.printStackTrace (Throwable.java:659)
    at java.lang.Throwable.printStackTrace (Throwable.java:722)
    at org.pitest.util.Log$PlainFormatter.format (Log.java:81)
    at java.util.logging.StreamHandler.publish (StreamHandler.java:211)
    at java.util.logging.ConsoleHandler.publish (ConsoleHandler.java:116)
    at java.util.logging.Logger.log (Logger.java:738)
    at java.util.logging.Logger.doLog (Logger.java:765)
    at java.util.logging.Logger.log (Logger.java:876)
    at org.pitest.util.CommunicationThread.waitToFinish (CommunicationThread.java:61)
    at org.pitest.coverage.execute.CoverageProcess.waitToDie (CoverageProcess.java:34)
    at org.pitest.coverage.execute.DefaultCoverageGenerator.gatherCoverageData (DefaultCoverageGenerator.java:138)
    at org.pitest.coverage.execute.DefaultCoverageGenerator.calculateCoverage (DefaultCoverageGenerator.java:90)
    at org.pitest.coverage.execute.DefaultCoverageGenerator.calculateCoverage (DefaultCoverageGenerator.java:52)
    at org.pitest.mutationtest.tooling.MutationCoverage.runAnalysis (MutationCoverage.java:148)
    at org.pitest.mutationtest.tooling.MutationCoverage.runReport (MutationCoverage.java:138)
    at org.pitest.mutationtest.tooling.EntryPoint.execute (EntryPoint.java:124)
    at org.pitest.mutationtest.tooling.EntryPoint.execute (EntryPoint.java:54)
    at org.pitest.maven.RunPitStrategy.execute (RunPitStrategy.java:35)
    at org.pitest.maven.AbstractPitMojo.analyse (AbstractPitMojo.java:504)
    at org.pitest.maven.AbstractPitMojo.execute (AbstractPitMojo.java:434)
    at org.apache.maven.plugin.DefaultBuildPluginManager.executeMojo (DefaultBuildPluginManager.java:137)
    at org.apache.maven.lifecycle.internal.MojoExecutor.execute (MojoExecutor.java:210)
[ERROR] 
[ERROR] 
[ERROR] For more information about the errors and possible solutions, please read the following articles:
[ERROR] [Help 1] http://cwiki.apache.org/confluence/display/MAVEN/OutOfMemoryError

mgonzcast avatar Jun 29 '22 08:06 mgonzcast

@hcoles any ideas of what can I try now to narrow down the issue?

mgonzcast avatar Jun 30 '22 07:06 mgonzcast

@mgonzcast If you set pitest's own logging to verbose (-Dverbose=true), then it might show something, although I'm not too hopeful.

After that it would be question of whittling away at the module to turn it into the smallest thing that reproduces the issue, and that you are happy to share (which can be done privately if that helps).

hcoles avatar Jun 30 '22 07:06 hcoles

If you set pitest's own logging to verbose (-Dverbose=true), then it might show something, although I'm not too hopeful.

@hcoles I did and I get this strange error (I replaced real strings for anonimity):

18:15:39 PIT >> INFO : MINION : 18:15:38 PIT >> SEVERE : Error while running adapter JUnit fixture class com.mycompany.com.mymodule with filter Optional[mymoduleTest(com.mycompany.com.mymodule)]
18:15:39 PIT >> FINE : MINION : org.pitest.util.PitError: PowerMock internal error: Should never throw exception at this level
18:16:02 PIT >> FINE : MINION :
18:16:02 PIT >> INFO : MINION : java.lang.RuntimeException: PowerMock internal error: Should never throw exception at this level
18:16:02 PIT >> FINE : MINION : Please copy and paste the information and the complete stacktrace below when reporting an issue
18:16:02 PIT >> INFO : MINION :         at org.powermock.modules.junit4.internal.impl.PowerMockJUnit44RunnerDelegateImpl$PowerMockJUnit44MethodRunner.handleException(PowerMockJUnit44RunnerDelegateImpl.java:384)

I don´t quite understand why It´s checking that module because I added to the list of Excluded classes, maybe I am excluding it wrongly?

Also I still see the socket error...maybe the antivirus is coming to play?

18:16:02 PIT >> FINE : MINION : Caused by: java.lang.RuntimeException: PowerMock internal error: Should never throw exception at this level
18:16:02 PIT >> INFO : MINION :         at javassist.ClassPoolTail.openClassfile(ClassPoolTail.java:340)
18:16:02 PIT >> FINE : MINION :         at org.powermock.modules.junit4.internal.impl.PowerMockJUnit44RunnerDelegateImpl$PowerMockJUnit44MethodRunner.handleException(PowerMockJUnit44RunnerDelegateImpl.java:384)
18:16:02 PIT >> INFO : MINION :         at javassist.ClassPoolTail.writeClassfile(ClassPoolTail.java:293)
18:16:02 PIT >> FINE : MINION :         at org.powermock.modules.junit4.internal.impl.PowerMockJUnit47RunnerDelegateImpl$PowerMockJUnit47MethodRunner.evaluateStatement(PowerMockJUnit47RunnerDelegateImpl.java:110)
18:16:02 PIT >> INFO : MINION :         at javassist.ClassPool.writeClassfile(ClassPool.java:627)
18:16:02 PIT >> FINE : MINION :         at org.powermock.modules.junit4.internal.impl.PowerMockJUnit47RunnerDelegateImpl$PowerMockJUnit47MethodRunner.executeTest(PowerMockJUnit47RunnerDelegateImpl.java:82)
18:16:02 PIT >> INFO : MINION :         at javassist.CtClassType.toBytecode(CtClassType.java:1589)
18:16:02 PIT >> FINE : MINION :         at org.powermock.modules.junit4.internal.impl.PowerMockJUnit44RunnerDelegateImpl$PowerMockJUnit44MethodRunner.runBeforesThenTestThenAfters(PowerMockJUnit44RunnerDelegateImpl.java:298)
18:16:02 PIT >> INFO : MINION :         at javassist.CtClass.toBytecode(CtClass.java:1519)
18:16:02 PIT >> FINE : MINION :         at org.junit.internal.runners.MethodRoadie.runTest(MethodRoadie.java:87)
18:16:02 PIT >> INFO : MINION :         at org.powermock.core.classloader.javassist.JavassistMockClassLoader.loadUnmockedClass(JavassistMockClassLoader.java:83)
18:16:02 PIT >> FINE : MINION :         at org.junit.internal.runners.MethodRoadie.run(MethodRoadie.java:50)
18:16:02 PIT >> INFO : MINION :         ... 33 more
18:16:02 PIT >> FINE : MINION :         at org.powermock.modules.junit4.internal.impl.PowerMockJUnit44RunnerDelegateImpl.invokeTestMethod(PowerMockJUnit44RunnerDelegateImpl.java:218)
18:16:02 PIT >> INFO : MINION : Caused by: java.net.SocketException: Software caused connection abort: socket write error
18:16:02 PIT >> FINE : MINION :         at org.powermock.modules.junit4.internal.impl.PowerMockJUnit44RunnerDelegateImpl.runMethods(PowerMockJUnit44RunnerDelegateImpl.java:160)
18:16:02 PIT >> INFO : MINION :         at java.net.SocketOutputStream.socketWrite0(Native Method)
18:16:02 PIT >> FINE : MINION :         at org.powermock.modules.junit4.internal.impl.PowerMockJUnit44RunnerDelegateImpl$1.run(PowerMockJUnit44RunnerDelegateImpl.java:134)
18:16:02 PIT >> INFO : MINION :         at java.net.SocketOutputStream.socketWrite(SocketOutputStream.java:111)
18:16:02 PIT >> FINE : MINION :         at org.junit.internal.runners.ClassRoadie.runUnprotected(ClassRoadie.java:34)
18:16:02 PIT >> INFO : MINION :         at java.net.SocketOutputStream.write(SocketOutputStream.java:155)
18:16:02 PIT >> FINE : MINION :         at org.junit.internal.runners.ClassRoadie.runProtected(ClassRoadie.java:44)
18:16:02 PIT >> INFO : MINION :         at java.io.BufferedOutputStream.flushBuffer(BufferedOutputStream.java:82)
18:16:02 PIT >> FINE : MINION :         at org.powermock.modules.junit4.internal.impl.PowerMockJUnit44RunnerDelegateImpl.run(PowerMockJUnit44RunnerDelegateImpl.java:136)
18:16:02 PIT >> INFO : MINION :         at java.io.BufferedOutputStream.write(BufferedOutputStream.java:126)
18:16:02 PIT >> FINE : MINION :         at org.powermock.modules.junit4.common.internal.impl.JUnit4TestSuiteChunkerImpl.run(JUnit4TestSuiteChunkerImpl.java:117)
18:16:02 PIT >> INFO : MINION :         at java.io.DataOutputStream.write(DataOutputStream.java:107)
18:16:02 PIT >> FINE : MINION :         at org.powermock.modules.junit4.common.internal.impl.AbstractCommonPowerMockRunner.run(AbstractCommonPowerMockRunner.java:57)
18:16:02 PIT >> INFO : MINION :         at java.io.FilterOutputStream.write(FilterOutputStream.java:97)
18:16:02 PIT >> FINE : MINION :         at org.powermock.modules.junit4.PowerMockRunner.run(PowerMockRunner.java:59)
18:16:02 PIT >> INFO : MINION :         at org.pitest.util.SafeDataOutputStream.writeBytes(SafeDataOutputStream.java:51)
18:16:02 PIT >> FINE : MINION :         at org.pitest.junit.adapter.CustomRunnerExecutor.run(CustomRunnerExecutor.java:42)
18:16:02 PIT >> INFO : MINION :         ... 44 more
18:16:02 PIT >> FINE : MINION :         at org.pitest.junit.adapter.AdaptedJUnitTestUnit.execute(AdaptedJUnitTestUnit.java:69)
18:16:02 PIT >> FINE : MINION :         ... 6 more
18:16:02 PIT >> FINE : MINION : Caused by: java.lang.RuntimeException: Failed to loaded class org.powermock.reflect.internal.WhiteboxImpl$2
18:16:02 PIT >> FINE : MINION :         at org.powermock.core.classloader.javassist.JavassistMockClassLoader.loadUnmockedClass(JavassistMockClassLoader.java:88)
18:16:02 PIT >> FINE : MINION :         at org.powermock.core.classloader.MockClassLoader.loadClassByThisClassLoader(MockClassLoader.java:104)
18:16:02 PIT >> FINE : MINION :         at org.powermock.core.classloader.DeferSupportingClassLoader.loadClass1(DeferSupportingClassLoader.java:147)
18:16:02 PIT >> FINE : MINION :         at org.powermock.core.classloader.DeferSupportingClassLoader.loadClass(DeferSupportingClassLoader.java:98)
18:16:02 PIT >> FINE : MINION :         at java.lang.ClassLoader.loadClass(ClassLoader.java:351)
18:16:02 PIT >> FINE : MINION :         at org.powermock.reflect.internal.WhiteboxImpl.doGetAllMethods(WhiteboxImpl.java:1497)
18:16:02 PIT >> FINE : MINION :         at org.powermock.reflect.internal.WhiteboxImpl.getAllMethods(WhiteboxImpl.java:1481)
18:16:02 PIT >> FINE : MINION :         at org.powermock.reflect.internal.WhiteboxImpl.findMethodOrThrowException(WhiteboxImpl.java:861)
18:16:02 PIT >> FINE : MINION :         at org.powermock.reflect.internal.WhiteboxImpl.doInvokeMethod(WhiteboxImpl.java:821)
18:16:02 PIT >> FINE : MINION :         at org.powermock.reflect.internal.WhiteboxImpl.invokeMethod(WhiteboxImpl.java:689)
18:16:02 PIT >> FINE : MINION :         at org.powermock.reflect.Whitebox.invokeMethod(Whitebox.java:401)
18:16:02 PIT >> FINE : MINION :         at org.powermock.modules.junit4.internal.impl.PowerMockJUnit44RunnerDelegateImpl$PowerMockJUnit44MethodRunner.handleException(PowerMockJUnit44RunnerDelegateImpl.java:361)
18:16:02 PIT >> FINE : MINION :         ... 22 more
18:16:02 PIT >> FINE : MINION : Caused by: org.pitest.util.PitError: Software caused connection abort: socket write error

mgonzcast avatar Jun 30 '22 16:06 mgonzcast