search

junit-team / junit5

✅ The 5th major version of the programmer-friendly testing framework for Java and the JVM
https://junit.org
Eclipse Public License 2.0
6.43k stars 1.49k forks source link

Java heap space issue #855

Closed vmassol closed 7 years ago

vmassol commented 7 years ago

Note: Issue created from #801

Seems using surefire 2.20 + JUnit5 is causing a java heap space issue, see https://jira.xwiki.org/browse/XCOMMONS-1189?focusedCommentId=94953&page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel#comment-94953

Note that running the exact same build by commenting out the following part doesn't exhibit the "Java Heap Space" issue so for some reason the junit5 provider is eating more memory. FTR I'm running with MAVEN_OPTS="-Xmx2048m -XX:MaxPermSize=196m" which is already quite substantial so it could be a memory leak somewhere.

        <plugin>
          <groupId>org.apache.maven.plugins</groupId>
          <artifactId>maven-surefire-plugin</artifactId>
          <!-- Lock down plugin version for build reproducibility -->
          <version>2.20</version>
...
          <dependencies>
            <!-- Allow running both JUnit4 and JUnit5 tests -->
            <!--dependency>
              <groupId>org.junit.platform</groupId>
              <artifactId>junit-platform-surefire-provider</artifactId>
              <version>1.0.0-M4</version>
            </dependency>
            <dependency>
              <groupId>org.junit.jupiter</groupId>
              <artifactId>junit-jupiter-engine</artifactId>
              <version>${junit5.version}</version>
            </dependency>
            <dependency>
              <groupId>org.junit.vintage</groupId>
              <artifactId>junit-vintage-engine</artifactId>
              <version>4.12.0-M4</version>
            </dependency-->
          </dependencies>
        </plugin>

Thanks

marcphilipp commented 7 years ago

Can you please post step-by-step instructions how I can reproduce this locally? Can you please take a heap dump and share it with us?

sbrannen commented 7 years ago

Please note that junit-platform-surefire-provider:1.0.0-M4 is not supported with maven-surefire-plugin:2.20.

junit-platform-surefire-provider:1.0.0-M4 is only supported with maven-surefire-plugin:2.19.

If you want to use maven-surefire-plugin:2.20 you will then have to build against a snapshot of the junit-platform-surefire-provider -- for example, version 1.0.0-SNAPSHOT.

shakuzen commented 7 years ago

@marcphilipp Here is a small project that reproduces the (I believe) same issue: https://github.com/shakuzen/junit-surefire-heap As the README states, just running ./mvnw test will reproduce.

This may be more of a Surefire 2.20 issue than a JUnit 5 issue*, but I personally was not able to reproduce it with JUnit 4 and Surefire 2.20. In my reproduction example, the equivalent test in JUnit 4 works fine with the Surefire plugin 2.20 (runs with ./mvnw -Pjunit4 test).

@sbrannen changing junit-platform-surefire-provider to SNAPSHOTs (1.0.0-SNAPSHOT) results in the same "Java heap space" build error in my above linked repro project.

* I say this because the Spring Boot project - not using JUnit 5 yet - seems to have ran into this problem when attempting to upgrade to surefire 2.20, per https://github.com/spring-projects/spring-boot/issues/6299#issuecomment-305883217

marcphilipp commented 7 years ago

@Tibor17 Are you aware of a memory leak in Surefire 2.20 as claimed by Spring Boot (see above)?

Tibor17 commented 7 years ago

No we dont have any leak.

vmassol commented 7 years ago

@sbrannen thanks. Yes, I'm using maven-surefire-plugin:2.20 with junit-platform-surefire-providerversion 1.0.0-SNAPSHOT (see thread #801 for details).

Similar to @shakuzen, I get the Java Heap space only with surefire 2.20 and junit-platform-surefire-providerversion 1.0.0-SNAPSHOT. I don't get it with surefire 2.19 and JUnit4 or surefire 2.20 and JUnit4.

Tibor17 commented 7 years ago

Guys find the root cause. 2.20 is a big change. I have no idea what leaks.

On Sat, Jun 10, 2017 at 5:38 PM, Vincent Massol notifications@github.com wrote:

@sbrannen https://github.com/sbrannen thanks. Yes, I'm using maven-surefire-plugin:2.20 with junit-platform-surefire-providerversion 1.0.0-SNAPSHOT (see thread #801 https://github.com/junit-team/junit5/issues/801 for details).

Similar to @shakuzen https://github.com/shakuzen, I get the Java Heap space only with surefire 2.20 and junit-platform-surefire-providerversion 1.0.0-SNAPSHOT. I don't get it with surefire 2.19 and JUnit4 or surefire 2.20 and JUnit4.

— You are receiving this because you were mentioned. Reply to this email directly, view it on GitHub https://github.com/junit-team/junit5/issues/855#issuecomment-307572534, or mute the thread https://github.com/notifications/unsubscribe-auth/AA_yR7-AsGp27lWIPuwwVR5J80eDU6t9ks5sCriNgaJpZM4Nd8x6 .

-- Cheers Tibor

vmassol commented 7 years ago

@Tibor17 I'm just trying to help you guys stabilize JUnit5 by reporting issues before you release JUnit5 as final (so that it's as stable as possible). However I don't have the time to help you debug it at this point, I'm quite busy with XWiki development itself... :) If I get some time in the future I'll sure help out more but don't wait for me.

marcphilipp commented 7 years ago

Since Spring Boot also has a problem with 2.20 (without using JUnit 5), the leak is most likely in Surefire and not in JUnit 5.

@Tibor17 Can you get in touch with Spring Boot?

vmassol commented 7 years ago

@marcphilipp Are you sure that's what @shakuzen said? AFAICS he said:

This may be more of a Surefire 2.20 issue than a JUnit 5 issue*, but I personally was not able to reproduce it with JUnit 4 and Surefire 2.20.

So to me it's more a JUnit5 issue (at least a JUnit5 + Surefire 2.20 combination issue).

marcphilipp commented 7 years ago

Well, Spring Boot seems to think it's Surefire: https://github.com/spring-projects/spring-boot/issues/9414

Tibor17 commented 7 years ago

You can use some tool from Oracle or divide the commit list, rebuild surefire, test and find the commit. Difficult.

On Sat, Jun 10, 2017 at 5:57 PM, Marc Philipp notifications@github.com wrote:

Well, Spring Boot seems to think it's Surefire: spring-projects/spring-boot#9414 https://github.com/spring-projects/spring-boot/issues/9414

— You are receiving this because you were mentioned. Reply to this email directly, view it on GitHub https://github.com/junit-team/junit5/issues/855#issuecomment-307573672, or mute the thread https://github.com/notifications/unsubscribe-auth/AA_yRzuXeHkCkGXoz7-y4Bjvn3BE77ojks5sCrz_gaJpZM4Nd8x6 .

-- Cheers Tibor

marcphilipp commented 7 years ago

Ok, I checked out @shakuzen's sample project.

Here are a couple of things I observed:

  1. The OutOfMemoryError happens in the Maven JVM, not in the forked JVM. That means that there's no memory leak in JUnit 5.
  2. In the heap dump, there's a single very large (>1GB) char array that contains the same content all over again "systemEnvironment]systemEnvironment]...". Any ideas where that might come from?
  3. Adding a very simple logback.xml file solved the [WARNING] Corrupted stdin stream in forked JVM 1. warning and the OutOfMemoryError (see https://github.com/shakuzen/junit-surefire-heap/pull/1/files). Probably because Logback disables java.util.logging.

So, (3) clearly points in the direction of logging, in particular since JUnit 5 uses java.util.logging while JUnit 4 does not.

@Tibor17 What changed in Surefire 2.20 with regard to stream handling? How can java.util.logging break it?

shakuzen commented 7 years ago

Just to add some information, in the dump file it contains messages like this for presumably every log message during test execution:

# Created on 2017-06-11T12:51:51.095
Corrupted stdin stream in forked JVM 1. Stream '12:51:51.094 [main] DEBUG org.springframework.beans.factory.support.DefaultListableBeanFactory - Returning cached instance of singleton bean 'lifecycleProcessor''.
java.lang.IllegalArgumentException: Stream stdin corrupted. Expected comma after third character in command '12:51:51.094 [main] DEBUG org.springframework.beans.factory.support.DefaultListableBeanFactory - Returning cached instance of singleton bean 'lifecycleProcessor''.
        at org.apache.maven.plugin.surefire.booterclient.output.ForkClient$OperationalData.<init>(ForkClient.java:469)
        at org.apache.maven.plugin.surefire.booterclient.output.ForkClient.processLine(ForkClient.java:191)
        at org.apache.maven.plugin.surefire.booterclient.output.ForkClient.consumeLine(ForkClient.java:158)
        at org.apache.maven.plugin.surefire.booterclient.output.ThreadedStreamConsumer$Pumper.run(ThreadedStreamConsumer.java:87)
        at java.lang.Thread.run(Thread.java:748)
Tibor17 commented 7 years ago

These errors have nothing to do with memory leaks. This is still the same bug you had with "XMLWriter" from dom4j. You are sending logs to the native stream System.out . Surefire overrides this stream and every test which calls System.out.println(data) the data is encoded in another stream which starts with command number. ForkClient recognizes the command number. If the format is broken you see :

Expected comma after third character in command

On Sun, Jun 11, 2017 at 7:37 AM, Tommy Ludwig notifications@github.com wrote:

Just to add some information, in the dump file it contains messages like this for presumably every log message during test execution:

Created on 2017-06-11T12:51:51.095

Corrupted stdin stream in forked JVM 1. Stream '12:51:51.094 [main] DEBUG org.springframework.beans.factory.support.DefaultListableBeanFactory - Returning cached instance of singleton bean 'lifecycleProcessor''. java.lang.IllegalArgumentException: Stream stdin corrupted. Expected comma after third character in command '12:51:51.094 [main] DEBUG org.springframework.beans.factory.support.DefaultListableBeanFactory - Returning cached instance of singleton bean 'lifecycleProcessor''. at org.apache.maven.plugin.surefire.booterclient.output.ForkClient$OperationalData.(ForkClient.java:469) at org.apache.maven.plugin.surefire.booterclient.output.ForkClient.processLine(ForkClient.java:191) at org.apache.maven.plugin.surefire.booterclient.output.ForkClient.consumeLine(ForkClient.java:158) at org.apache.maven.plugin.surefire.booterclient.output.ThreadedStreamConsumer$Pumper.run(ThreadedStreamConsumer.java:87) at java.lang.Thread.run(Thread.java:748)

— You are receiving this because you were mentioned. Reply to this email directly, view it on GitHub https://github.com/junit-team/junit5/issues/855#issuecomment-307608065, or mute the thread https://github.com/notifications/unsubscribe-auth/AA_yR1X1XIFu6lw1YsbzjgXmqQyGtMJRks5sC30vgaJpZM4Nd8x6 .

-- Cheers Tibor

Tibor17 commented 7 years ago

Stream format till version 2.20 has not changed. We only made users error more visible. We cannot fix users error. All these suspicions are now visible and we want to prevent from permanently opening Jira bugs.

On Mon, Jun 12, 2017 at 1:15 AM, Tibor Digana tibor.digana@googlemail.com wrote:

These errors have nothing to do with memory leaks. This is still the same bug you had with "XMLWriter" from dom4j. You are sending logs to the native stream System.out . Surefire overrides this stream and every test which calls System.out.println(data) the data is encoded in another stream which starts with command number. ForkClient recognizes the command number. If the format is broken you see :

Expected comma after third character in command

On Sun, Jun 11, 2017 at 7:37 AM, Tommy Ludwig notifications@github.com wrote:

Just to add some information, in the dump file it contains messages like this for presumably every log message during test execution:

Created on 2017-06-11T12:51:51.095

Corrupted stdin stream in forked JVM 1. Stream '12:51:51.094 [main] DEBUG org.springframework.beans.factory.support.DefaultListableBeanFactory - Returning cached instance of singleton bean 'lifecycleProcessor''. java.lang.IllegalArgumentException: Stream stdin corrupted. Expected comma after third character in command '12:51:51.094 [main] DEBUG org.springframework.beans.factory.support.DefaultListableBeanFactory - Returning cached instance of singleton bean 'lifecycleProcessor''. at org.apache.maven.plugin.surefire.booterclient.output.ForkClient$OperationalData.(ForkClient.java:469) at org.apache.maven.plugin.surefire.booterclient.output.ForkClient.processLine(ForkClient.java:191) at org.apache.maven.plugin.surefire.booterclient.output.ForkClient.consumeLine(ForkClient.java:158) at org.apache.maven.plugin.surefire.booterclient.output.ThreadedStreamConsumer$Pumper.run(ThreadedStreamConsumer.java:87) at java.lang.Thread.run(Thread.java:748)

— You are receiving this because you were mentioned. Reply to this email directly, view it on GitHub https://github.com/junit-team/junit5/issues/855#issuecomment-307608065, or mute the thread https://github.com/notifications/unsubscribe-auth/AA_yR1X1XIFu6lw1YsbzjgXmqQyGtMJRks5sC30vgaJpZM4Nd8x6 .

-- Cheers Tibor

-- Cheers Tibor

shakuzen commented 7 years ago

After analyzing the heap dump, I realized there was an infinite loop in the surefire code. It looks like someone else also realized this and already fixed it in https://github.com/apache/maven-surefire/commit/7176d3c17b438c60e48a525ef96e6812f00bec46 which will be in surefire 2.20.1 per SUREFIRE-1382. Therefore, I believe this issue can be closed. I haven't been able to confirm because running my sample with surefire 2.21-SNAPSHOT fails for an unrelated reason I'm unable to look into now.

vmassol commented 7 years ago

@shakuzen Thanks for posting the explanation and links! Great that it's fixed. Waiting eagerly for Surefire 2.20.1 :)

marcphilipp commented 7 years ago

@Tibor17 When is 2.20.1 going to be released?

marcphilipp commented 7 years ago

Closing in favor of #809.

Tibor17 commented 7 years ago

This issue was fixed in 2.21-SNAPSHOT.

On Mon, Jul 10, 2017 at 12:41 PM, Marc Philipp notifications@github.com wrote:

Closed #855 https://github.com/junit-team/junit5/issues/855.

— You are receiving this because you were mentioned. Reply to this email directly, view it on GitHub https://github.com/junit-team/junit5/issues/855#event-1156551960, or mute the thread https://github.com/notifications/unsubscribe-auth/AA_yRxWfWBpLAoymimcHCxL0b_GNW28zks5sMf_ngaJpZM4Nd8x6 .

-- Cheers Tibor

marcphilipp commented 7 years ago

@Tibor17 Thanks for chiming in! So, will there be a 2.20.1 or do we have to wait for 2.21?

Tibor17 commented 7 years ago

The will be 2.20.1. I made fix for Jira SUREFIRE-1302 but I found I was too fast so I have to override HEAD commit. I have to rework it totally. I am testing on Windows/Ubuntu/Fedora and my colleague on FreeBSD. We still have some doubts.

On Mon, Jul 10, 2017 at 1:25 PM, Marc Philipp notifications@github.com wrote:

@Tibor17 https://github.com/tibor17 Thanks for chiming in! So, will there be a 2.20.1 or do we have to wait for 2.21?

— You are receiving this because you were mentioned. Reply to this email directly, view it on GitHub https://github.com/junit-team/junit5/issues/855#issuecomment-314078525, or mute the thread https://github.com/notifications/unsubscribe-auth/AA_yRwbv8Uq2LvE7_znate7PfKWWV0uoks5sMgoagaJpZM4Nd8x6 .

-- Cheers Tibor