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

        Activity

        Magnus Naeslund created issue -
        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?
        Tibor Digana made changes -
        Field Original Value New Value
        Assignee Tibor Digana [ tibor17 ]
        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.
        Tibor Digana made changes -
        Fix Version/s 2.19 [ 20728 ]
        Hide
        Tibor Digana added a comment -

        commit 8e05b10c95d632db2aceecbb4f570e2b07002378

        Show
        Tibor Digana added a comment - commit 8e05b10c95d632db2aceecbb4f570e2b07002378
        Tibor Digana made changes -
        Status Open [ 1 ] Closed [ 6 ]
        Resolution Fixed [ 1 ]
        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.
        Andreas Gudian made changes -
        Fix Version/s 2.19 [ 20728 ]
        Fix Version/s 2.18.1 [ 20814 ]
        Mark Thomas made changes -
        Project Import Sun Apr 05 13:23:32 UTC 2015 [ 1428240212200 ]
        Mark Thomas made changes -
        Workflow jira [ 12728104 ] Default workflow, editable Closed status [ 12759170 ]
        Mark Thomas made changes -
        Project Import Mon Apr 06 01:36:33 UTC 2015 [ 1428284193036 ]
        Mark Thomas made changes -
        Workflow jira [ 12965172 ] Default workflow, editable Closed status [ 13002196 ]
        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.
        Transition Time In Source Status Execution Times Last Executer Last Execution Date
        Open Open Closed Closed
        945d 11h 7m 1 Tibor Digana 12/Nov/14 15:32

          People

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

            Dates

            • Created:
              Updated:
              Resolved:

              Development