Maven Surefire
  1. Maven Surefire
  2. SUREFIRE-859

Exception in thread "TreadedStreamConsumer" java.lang.RuntimeException during GC

    Details

      Description

      When executing 151 integration tests with 829 test methods on a Solaris machine, there is an exception:
      ===
      Exception in thread "ThreadStreamConsumer" java.lang.RuntimeException: 176: [GC 100,177: [ParNew
      ...
      java.langh.RuntimeException: The forked VM terminated without saying properly goodbye. VM crash or System.exit called ?
      ===
      (see attachment for full stack traces)

      The message of the RuntimeException suggests that the problem is connected to garbage collection. The stack trace points to ForkClient.java. It looks as if the method "consumeLine" in ForkClient.java is fed with GC information instead of the expected string.

      The exception occurs with concurrency configuration "parallel='none'" as well as with "parallel='classes'" in both versions of the surefire plugin, 2.11 and 2.12.

      However, this problem does not show up on a Windows/Cygwin environment.

      1. runtimeexception.txt
        14 kB
        Magnus Naeslund

        Issue Links

          Activity

          Hide
          Tibor Digana added a comment -

          Can you provide the configuration of surefire plugin?

          Show
          Tibor Digana added a comment - Can you provide the configuration of surefire plugin?
          Hide
          Andreas Gudian added a comment -

          This may look more like an issue of the JRE that was used here. Probably, the GC-Info printed by the VM is not routed through the System.out, but directly from the native JVM code to stdout.

          Would be worth checking if current JVMs still do that, and in that case adapt the ForkClient to ignore any lines that do not start with the expected prefixes.

          Show
          Andreas Gudian added a comment - This may look more like an issue of the JRE that was used here. Probably, the GC-Info printed by the VM is not routed through the System.out, but directly from the native JVM code to stdout. Would be worth checking if current JVMs still do that, and in that case adapt the ForkClient to ignore any lines that do not start with the expected prefixes.
          Hide
          Tibor Digana added a comment -

          yes @Andreas, this was my guess what's happening in that stream as well.
          I will check it out.

          Show
          Tibor Digana added a comment - yes @Andreas, this was my guess what's happening in that stream as well. I will check it out.
          Hide
          Tibor Digana added a comment -

          @Mag would you have time to check the fix with new snapshot version?
          The same JVM and machine should be used again.

          Show
          Tibor Digana added a comment - @Mag would you have time to check the fix with new snapshot version? The same JVM and machine should be used again.
          Hide
          Tibor Digana added a comment -

          I could not reproduce this issue with Maven 3.2.1 and x86 JDK 8.
          From my PoV this is JVM issue.
          I will fix it anyway, suppress the fault, and the SUREFIRE would not fail. You will see an error message in log instead.

          I have tested SUREFIRE with JVM options :

          export MAVEN_OPTS=-XX:+CMSParallelRemarkEnabled -XX:+UseConcMarkSweepGC -XX:+UseParNewGC -XX:+PrintGCApplicationStoppedTime -XX:+PrintGCApplicationConcurrentTime -XX:+PrintGCDetails -XX:+PrintGCTimeStamps -XX:+PrintGCDateStamps -XX:+PrintHeapAtGC -XX:+PrintTenuringDistribution -verbose:gc

          I set the same options in the plugin parameter "argLine".
          Other parameter forkMode=always.

          Show
          Tibor Digana added a comment - I could not reproduce this issue with Maven 3.2.1 and x86 JDK 8. From my PoV this is JVM issue. I will fix it anyway, suppress the fault, and the SUREFIRE would not fail. You will see an error message in log instead. I have tested SUREFIRE with JVM options : export MAVEN_OPTS=-XX:+CMSParallelRemarkEnabled -XX:+UseConcMarkSweepGC -XX:+UseParNewGC -XX:+PrintGCApplicationStoppedTime -XX:+PrintGCApplicationConcurrentTime -XX:+PrintGCDetails -XX:+PrintGCTimeStamps -XX:+PrintGCDateStamps -XX:+PrintHeapAtGC -XX:+PrintTenuringDistribution -verbose:gc I set the same options in the plugin parameter "argLine". Other parameter forkMode=always.
          Hide
          Tibor Digana added a comment -

          commit 8e05b10c95d632db2aceecbb4f570e2b07002378

          Show
          Tibor Digana added a comment - commit 8e05b10c95d632db2aceecbb4f570e2b07002378
          Hide
          Magnus Naeslund added a comment - - edited

          Thanks for fixing the problem. Unfortunately, the setup in which the exception was originally thrown is no longer in available to me.

          Show
          Magnus Naeslund added a comment - - edited Thanks for fixing the problem. Unfortunately, the setup in which the exception was originally thrown is no longer in available to me.
          Hide
          Tibor Digana added a comment -

          @Mag
          It was a simple fix. We are a small group of Maven developers. I would like to ask you to participate in development from time to time. A lot of Maven projects like surefire are available on GitHub as well.

          Show
          Tibor Digana added a comment - @Mag It was a simple fix. We are a small group of Maven developers. I would like to ask you to participate in development from time to time. A lot of Maven projects like surefire are available on GitHub as well.
          Hide
          ASF GitHub Bot added a comment -

          Github user m4rkmckenna commented on the pull request:

          https://github.com/apache/incubator-brooklyn/pull/1068#issuecomment-159575709

          From having run locally I get the below log ... no failure but `GC (Allocation Failure)` is interesting can any one shed any light on this? From what i understand java is trying to allocate memory and failing so GC is kicking in (this may be unrelated)
          ```
          2015-11-25 10:46:45,697 INFO TESTNG PASSED: "Surefire test" - org.apache.brooklyn.rest.client.BrooklynApiRestClientTest.testLocationApi() finished in 8 ms
          2015-11-25 10:46:45,698 INFO TESTNG INVOKING CONFIGURATION: "Surefire test" - @AfterClass org.apache.brooklyn.rest.client.BrooklynApiRestClientTest.tearDown()
          SUREFIRE-859: [GC (Allocation Failure) 217399K->33627K(753664K), 0.0062667 secs]
          SUREFIRE-859: [GC (Allocation Failure) 230235K->45522K(755712K), 0.0161661 secs]
          SUREFIRE-859: [GC (Allocation Failure) 255442K->63523K(760320K), 0.0228548 secs]
          SUREFIRE-859: [GC (Allocation Failure) 273443K->77064K(726528K), 0.0192347 secs]
          SUREFIRE-859: [GC (Allocation Failure) 253192K->88147K(729088K), 0.0135007 secs]
          SUREFIRE-859: [GC (Allocation Failure) 264275K->88834K(743424K), 0.0113851 secs]
          SUREFIRE-859: [GC (Allocation Failure) 264450K->89195K(742912K), 0.0091640 secs]
          2015-11-25 10:46:47,978 INFO TESTNG PASSED CONFIGURATION: "Surefire test" - @AfterClass org.apache.brooklyn.rest.client.BrooklynApiRestClientTest.tearDown() finished in 2281 ms
          ```

          Show
          ASF GitHub Bot added a comment - Github user m4rkmckenna commented on the pull request: https://github.com/apache/incubator-brooklyn/pull/1068#issuecomment-159575709 From having run locally I get the below log ... no failure but `GC (Allocation Failure)` is interesting can any one shed any light on this? From what i understand java is trying to allocate memory and failing so GC is kicking in (this may be unrelated) ``` 2015-11-25 10:46:45,697 INFO TESTNG PASSED: "Surefire test" - org.apache.brooklyn.rest.client.BrooklynApiRestClientTest.testLocationApi() finished in 8 ms 2015-11-25 10:46:45,698 INFO TESTNG INVOKING CONFIGURATION: "Surefire test" - @AfterClass org.apache.brooklyn.rest.client.BrooklynApiRestClientTest.tearDown() SUREFIRE-859 : [GC (Allocation Failure) 217399K->33627K(753664K), 0.0062667 secs] SUREFIRE-859 : [GC (Allocation Failure) 230235K->45522K(755712K), 0.0161661 secs] SUREFIRE-859 : [GC (Allocation Failure) 255442K->63523K(760320K), 0.0228548 secs] SUREFIRE-859 : [GC (Allocation Failure) 273443K->77064K(726528K), 0.0192347 secs] SUREFIRE-859 : [GC (Allocation Failure) 253192K->88147K(729088K), 0.0135007 secs] SUREFIRE-859 : [GC (Allocation Failure) 264275K->88834K(743424K), 0.0113851 secs] SUREFIRE-859 : [GC (Allocation Failure) 264450K->89195K(742912K), 0.0091640 secs] 2015-11-25 10:46:47,978 INFO TESTNG PASSED CONFIGURATION: "Surefire test" - @AfterClass org.apache.brooklyn.rest.client.BrooklynApiRestClientTest.tearDown() finished in 2281 ms ```
          Hide
          ASF GitHub Bot added a comment -

          Github user neykov commented on the pull request:

          https://github.com/apache/incubator-brooklyn/pull/1068#issuecomment-159577361

          @m4rkmckenna It's unrelated.
          My understanding of the issue (https://issues.apache.org/jira/browse/SUREFIRE-859) is that surefire is consuming the output of the test process when it sees unexpected format, caused by verbose garbage collection (configured by us). So it will just print the unrecognized output as is.

          The output itself means that the garbage collector has kicked in because of a failure to allocate a buffer, giving some statistics about the gc run.

          Just ignore it.

          Show
          ASF GitHub Bot added a comment - Github user neykov commented on the pull request: https://github.com/apache/incubator-brooklyn/pull/1068#issuecomment-159577361 @m4rkmckenna It's unrelated. My understanding of the issue ( https://issues.apache.org/jira/browse/SUREFIRE-859 ) is that surefire is consuming the output of the test process when it sees unexpected format, caused by verbose garbage collection (configured by us). So it will just print the unrecognized output as is. The output itself means that the garbage collector has kicked in because of a failure to allocate a buffer, giving some statistics about the gc run. Just ignore it.
          Hide
          ASF GitHub Bot added a comment -

          Github user Tibor17 commented on the pull request:

          https://github.com/apache/incubator-brooklyn/pull/1068#issuecomment-159588763

          In Surefire 2.19 the prefix "SUREFIRE-859: " was removed.

          Show
          ASF GitHub Bot added a comment - Github user Tibor17 commented on the pull request: https://github.com/apache/incubator-brooklyn/pull/1068#issuecomment-159588763 In Surefire 2.19 the prefix " SUREFIRE-859 : " was removed.
          Hide
          ASF GitHub Bot added a comment -

          Github user neykov commented on the issue:

          https://github.com/apache/brooklyn-server/pull/426

          Looks good and works much better, see the [new build](https://builds.apache.org/view/Brooklyn/job/brooklyn-integration-tests/52/console)

          ```
          2016-11-10 15:47:31,205 INFO TESTNG INVOKING: "Surefire test" - org.apache.brooklyn.util.javalang.MemoryUsageTrackerTest.testSoftUsageAndClearance()
          2016-11-10 15:47:31,206 INFO Memory usage at start of test: MemoryUsageSummary

          {total=772 MB, free=652 MB, used=120 MB, usedFraction=0.1555049937704335}

          SUREFIRE-859: [GC (Allocation Failure) 265638K->264541K(753664K), 0.0252673 secs]
          SUREFIRE-859: [GC (Allocation Failure) 460429K->459760K(753152K), 0.0260455 secs]
          SUREFIRE-859: [Full GC (Ergonomics) 459760K->351817K(753152K), 0.0518254 secs]
          SUREFIRE-859: [Full GC (Ergonomics) 548263K->548101K(753152K), 0.1852436 secs]
          SUREFIRE-859: [Full GC (Ergonomics) 719375K->718997K(753152K), 0.0680970 secs]
          SUREFIRE-859: [Full GC (Ergonomics) 720275K->719974K(753152K), 0.0546380 secs]
          SUREFIRE-859: [Full GC (Allocation Failure) 719974K->8048K(753152K), 0.0267869 secs]
          2016-11-10 15:47:31,782 INFO First soft reference cleared after 730 1M blocks created; 729 of them cleared; memory just before collected is MemoryUsageSummary

          {total=771 MB, free=33.7 MB, used=738 MB, usedFraction=0.9563477890253229}

          SUREFIRE-859: [Full GC (Ergonomics) 704594K->702492K(753152K), 0.2032216 secs]
          SUREFIRE-859: [Full GC (Ergonomics) 712258K->711185K(753152K), 0.0347821 secs]
          SUREFIRE-859: [Full GC (Allocation Failure) 711185K->711185K(753152K), 0.0322254 secs]
          SUREFIRE-859: [Full GC (System.gc()) 711185K->8055K(753152K), 0.0285412 secs]
          SUREFIRE-859: [GC (System.gc()) 8055K->8055K(645632K), 0.0029759 secs]
          SUREFIRE-859: [Full GC (System.gc()) 8055K->8055K(645632K), 0.0225672 secs]
          2016-11-10 15:47:32,244 INFO Forcing memory eviction: allocated 725 MB +- 5 MB really free memory in 10 MB chunks; memory used from 11.5 MB -> 8.25 MB / 661 MB
          SUREFIRE-859: [GC (System.gc()) 9315K->8215K(699392K), 0.0011906 secs]
          SUREFIRE-859: [Full GC (System.gc()) 8215K->8063K(699392K), 0.0333181 secs]
          SUREFIRE-859: [GC (System.gc()) 8063K->8063K(699392K), 0.0021073 secs]
          SUREFIRE-859: [Full GC (System.gc()) 8063K->8063K(699392K), 0.0225468 secs]
          2016-11-10 15:47:32,305 INFO Final memory usage (after forcing clear, and GC): MemoryUsageSummary

          {total=716 MB, free=708 MB, used=8.26 MB, usedFraction=0.01152881940671326}

          2016-11-10 15:47:32,305 INFO TESTNG PASSED: "Surefire test" - org.apache.brooklyn.util.javalang.MemoryUsageTrackerTest.testSoftUsageAndClearance() finished in 1100 ms
          ```

          Merging.

          Show
          ASF GitHub Bot added a comment - Github user neykov commented on the issue: https://github.com/apache/brooklyn-server/pull/426 Looks good and works much better, see the [new build] ( https://builds.apache.org/view/Brooklyn/job/brooklyn-integration-tests/52/console ) ``` 2016-11-10 15:47:31,205 INFO TESTNG INVOKING: "Surefire test" - org.apache.brooklyn.util.javalang.MemoryUsageTrackerTest.testSoftUsageAndClearance() 2016-11-10 15:47:31,206 INFO Memory usage at start of test: MemoryUsageSummary {total=772 MB, free=652 MB, used=120 MB, usedFraction=0.1555049937704335} SUREFIRE-859 : [GC (Allocation Failure) 265638K->264541K(753664K), 0.0252673 secs] SUREFIRE-859 : [GC (Allocation Failure) 460429K->459760K(753152K), 0.0260455 secs] SUREFIRE-859 : [Full GC (Ergonomics) 459760K->351817K(753152K), 0.0518254 secs] SUREFIRE-859 : [Full GC (Ergonomics) 548263K->548101K(753152K), 0.1852436 secs] SUREFIRE-859 : [Full GC (Ergonomics) 719375K->718997K(753152K), 0.0680970 secs] SUREFIRE-859 : [Full GC (Ergonomics) 720275K->719974K(753152K), 0.0546380 secs] SUREFIRE-859 : [Full GC (Allocation Failure) 719974K->8048K(753152K), 0.0267869 secs] 2016-11-10 15:47:31,782 INFO First soft reference cleared after 730 1M blocks created; 729 of them cleared; memory just before collected is MemoryUsageSummary {total=771 MB, free=33.7 MB, used=738 MB, usedFraction=0.9563477890253229} SUREFIRE-859 : [Full GC (Ergonomics) 704594K->702492K(753152K), 0.2032216 secs] SUREFIRE-859 : [Full GC (Ergonomics) 712258K->711185K(753152K), 0.0347821 secs] SUREFIRE-859 : [Full GC (Allocation Failure) 711185K->711185K(753152K), 0.0322254 secs] SUREFIRE-859 : [Full GC (System.gc()) 711185K->8055K(753152K), 0.0285412 secs] SUREFIRE-859 : [GC (System.gc()) 8055K->8055K(645632K), 0.0029759 secs] SUREFIRE-859 : [Full GC (System.gc()) 8055K->8055K(645632K), 0.0225672 secs] 2016-11-10 15:47:32,244 INFO Forcing memory eviction: allocated 725 MB +- 5 MB really free memory in 10 MB chunks; memory used from 11.5 MB -> 8.25 MB / 661 MB SUREFIRE-859 : [GC (System.gc()) 9315K->8215K(699392K), 0.0011906 secs] SUREFIRE-859 : [Full GC (System.gc()) 8215K->8063K(699392K), 0.0333181 secs] SUREFIRE-859 : [GC (System.gc()) 8063K->8063K(699392K), 0.0021073 secs] SUREFIRE-859 : [Full GC (System.gc()) 8063K->8063K(699392K), 0.0225468 secs] 2016-11-10 15:47:32,305 INFO Final memory usage (after forcing clear, and GC): MemoryUsageSummary {total=716 MB, free=708 MB, used=8.26 MB, usedFraction=0.01152881940671326} 2016-11-10 15:47:32,305 INFO TESTNG PASSED: "Surefire test" - org.apache.brooklyn.util.javalang.MemoryUsageTrackerTest.testSoftUsageAndClearance() finished in 1100 ms ``` Merging.
          Hide
          ASF GitHub Bot added a comment -

          Github user Tibor17 commented on the issue:

          https://github.com/apache/brooklyn-server/pull/426

          @aledsage
          The prefix `SUREFIRE-859` does not exist in the console.
          Is it fine for you?

          Show
          ASF GitHub Bot added a comment - Github user Tibor17 commented on the issue: https://github.com/apache/brooklyn-server/pull/426 @aledsage The prefix ` SUREFIRE-859 ` does not exist in the console. Is it fine for you?
          Hide
          ASF GitHub Bot added a comment -

          Github user aledsage commented on the issue:

          https://github.com/apache/brooklyn-server/pull/426

          @Tibor17 not sure what you mean by "The prefix `SUREFIRE-859` does not exist in the console."

          I see the output that @neykov pasted when I follow the link to https://builds.apache.org/view/Brooklyn/job/brooklyn-integration-tests/52/console.

          When I run locally (e.g. with `mvn test -Dtest=MemoryUsageTrackerTest#testSoftUsageAndClearance`) then I see the same `SUREFIRE` prefixes for the memory usage. This is because of the `-verbose:gc` at https://github.com/apache/brooklyn-server/blob/master/parent/pom.xml#L691

          Show
          ASF GitHub Bot added a comment - Github user aledsage commented on the issue: https://github.com/apache/brooklyn-server/pull/426 @Tibor17 not sure what you mean by "The prefix ` SUREFIRE-859 ` does not exist in the console." I see the output that @neykov pasted when I follow the link to https://builds.apache.org/view/Brooklyn/job/brooklyn-integration-tests/52/console . When I run locally (e.g. with `mvn test -Dtest=MemoryUsageTrackerTest#testSoftUsageAndClearance`) then I see the same `SUREFIRE` prefixes for the memory usage. This is because of the `-verbose:gc` at https://github.com/apache/brooklyn-server/blob/master/parent/pom.xml#L691
          Hide
          ASF GitHub Bot added a comment -

          Github user ahgittin commented on the issue:

          https://github.com/apache/brooklyn-server/pull/426

          The `SUREFIRE-859` prefix lines may depend on which JVM is being used?

          Show
          ASF GitHub Bot added a comment - Github user ahgittin commented on the issue: https://github.com/apache/brooklyn-server/pull/426 The ` SUREFIRE-859 ` prefix lines may depend on which JVM is being used?

            People

            • Assignee:
              Tibor Digana
              Reporter:
              Magnus Naeslund
            • Votes:
              0 Vote for this issue
              Watchers:
              6 Start watching this issue

              Dates

              • Created:
                Updated:
                Resolved:

                Development