[jira] [Commented] (MNG-6340) [Performance]To make System.gc() call configurable in target summary code
[
https://issues.apache.org/jira/browse/MNG-6340?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=17069744#comment-17069744
]
Hudson commented on MNG-6340:
-
Build failed in Jenkins: Maven TLP » maven-studies » maven-metrics #4
See
https://builds.apache.org/job/maven-box/job/maven-studies/job/maven-metrics/4/
> [Performance]To make System.gc() call configurable in target summary code
> -
>
> Key: MNG-6340
> URL: https://issues.apache.org/jira/browse/MNG-6340
> Project: Maven
> Issue Type: Improvement
> Components: Design, Patterns & Best Practices
>Affects Versions: 3.5.2
> Environment: Linux, AWS, OpenStack
>Reporter: Tony Guan
>Assignee: Karl Heinz Marbaise
>Priority: Minor
> Labels: performance
> Fix For: 3.5.3
>
>
> While investigating our internal builds (powered by Maven), I found that the
> in the maven target stats report, there is a big gap between the line of
> "Finished at ..." and "Final Memory...".
> Depending on the Java heap size, there were 15 seconds to 30 seconds gap in
> the two lines. (Your mileage may vary)
> Samples are (31 seconds below):
> 17:20:57.728 I [-@main] Finished at: 2017-10-26T17:20:57+00:00
> 17:21:28.105 I [-@main] Final Memory: 3352M/9102M
> Further investigation showed that the big gap lies in the System.gc() call in
> maven code:
> [https://github.com/apache/maven/blob/f5f76c70e1828a7e6c6267fc4bc53abc35c19ce7/maven-embedder/src/main/java/org/apache/maven/cli/event/ExecutionEventLogger.java]
> The problematic code is here:
> {code:java}
> private void logStats( MavenSession session )
> {
> infoLine( '-' );
> long finish = System.currentTimeMillis();
> long time = finish - session.getRequest().getStartTime().getTime();
> String wallClock = session.getRequest().getDegreeOfConcurrency() > 1 ? "
> (Wall Clock)" : "";
> logger.info( "Total time: " + formatDuration( time ) + wallClock );
> logger.info( "Finished at: " + formatTimestamp( finish ) );
> System.gc();
> Runtime r = Runtime.getRuntime();
> long mb = 1024 * 1024;
> logger.info( "Final Memory: " + ( r.totalMemory() - r.freeMemory() ) / mb +
> "M/" + r.totalMemory() / mb + "M" );
> }
> {code}
> It turns out that for each executed target, there is a Full GC invoked, just
> in order to get the memory summary. The intention may be good, so you can
> investigate the heap footprint. But this hurts performance in an accumulated
> way, and most users are not aware of this losing cpu cycles using Maven.
> Simple calculation for the cost of this coding: let's say Maven averages
> active N users, and these N users are using Maven to build everyday for T
> targets, then we have an estimate that N*T full GCs will be incurred everyday.
> These Full GCs average H hours, then N*T*H is the time wasted.
> Assuming they all use AWS for the builds, then it can be translated to money
> they have to pay to cloud providers unnecessary.
> So we should make this "memory stats after mvn target execution" disabled by
> default. Of course, it's better to provide a parameter to disable/enable this
> summary line for more flexibility.
> For current users, if you want to do something about this waste, the remedy
> is simple too: you can just add a JVM option -XX:+DisableExplicitGC from
> maven configuration.
>
--
This message was sent by Atlassian Jira
(v8.3.4#803005)
[jira] [Commented] (MNG-6340) [Performance]To make System.gc() call configurable in target summary code
[
https://issues.apache.org/jira/browse/MNG-6340?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=16351850#comment-16351850
]
Hudson commented on MNG-6340:
-
Build succeeded in Jenkins: Maven TLP (wip) » maven » master #32
See https://builds.apache.org/job/maven-wip/job/maven/job/master/32/
> [Performance]To make System.gc() call configurable in target summary code
> -
>
> Key: MNG-6340
> URL: https://issues.apache.org/jira/browse/MNG-6340
> Project: Maven
> Issue Type: Improvement
> Components: Design, Patterns & Best Practices
>Affects Versions: 3.5.2
> Environment: Linux, AWS, OpenStack
>Reporter: Tony Guan
>Assignee: Karl Heinz Marbaise
>Priority: Minor
> Labels: performance
> Fix For: 3.5.3
>
>
> While investigating our internal builds (powered by Maven), I found that the
> in the maven target stats report, there is a big gap between the line of
> "Finished at ..." and "Final Memory...".
> Depending on the Java heap size, there were 15 seconds to 30 seconds gap in
> the two lines. (Your mileage may vary)
> Samples are (31 seconds below):
> 17:20:57.728 I [-@main] Finished at: 2017-10-26T17:20:57+00:00
> 17:21:28.105 I [-@main] Final Memory: 3352M/9102M
> Further investigation showed that the big gap lies in the System.gc() call in
> maven code:
> [https://github.com/apache/maven/blob/f5f76c70e1828a7e6c6267fc4bc53abc35c19ce7/maven-embedder/src/main/java/org/apache/maven/cli/event/ExecutionEventLogger.java]
> The problematic code is here:
> {code:java}
> private void logStats( MavenSession session )
> {
> infoLine( '-' );
> long finish = System.currentTimeMillis();
> long time = finish - session.getRequest().getStartTime().getTime();
> String wallClock = session.getRequest().getDegreeOfConcurrency() > 1 ? "
> (Wall Clock)" : "";
> logger.info( "Total time: " + formatDuration( time ) + wallClock );
> logger.info( "Finished at: " + formatTimestamp( finish ) );
> System.gc();
> Runtime r = Runtime.getRuntime();
> long mb = 1024 * 1024;
> logger.info( "Final Memory: " + ( r.totalMemory() - r.freeMemory() ) / mb +
> "M/" + r.totalMemory() / mb + "M" );
> }
> {code}
> It turns out that for each executed target, there is a Full GC invoked, just
> in order to get the memory summary. The intention may be good, so you can
> investigate the heap footprint. But this hurts performance in an accumulated
> way, and most users are not aware of this losing cpu cycles using Maven.
> Simple calculation for the cost of this coding: let's say Maven averages
> active N users, and these N users are using Maven to build everyday for T
> targets, then we have an estimate that N*T full GCs will be incurred everyday.
> These Full GCs average H hours, then N*T*H is the time wasted.
> Assuming they all use AWS for the builds, then it can be translated to money
> they have to pay to cloud providers unnecessary.
> So we should make this "memory stats after mvn target execution" disabled by
> default. Of course, it's better to provide a parameter to disable/enable this
> summary line for more flexibility.
> For current users, if you want to do something about this waste, the remedy
> is simple too: you can just add a JVM option -XX:+DisableExplicitGC from
> maven configuration.
>
--
This message was sent by Atlassian JIRA
(v7.6.3#76005)
[jira] [Commented] (MNG-6340) [Performance]To make System.gc() call configurable in target summary code
[
https://issues.apache.org/jira/browse/MNG-6340?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=16351848#comment-16351848
]
Hudson commented on MNG-6340:
-
Build succeeded in Jenkins: maven-3.x-jenkinsfile » master #161
See https://builds.apache.org/job/maven-3.x-jenkinsfile/job/master/161/
> [Performance]To make System.gc() call configurable in target summary code
> -
>
> Key: MNG-6340
> URL: https://issues.apache.org/jira/browse/MNG-6340
> Project: Maven
> Issue Type: Improvement
> Components: Design, Patterns & Best Practices
>Affects Versions: 3.5.2
> Environment: Linux, AWS, OpenStack
>Reporter: Tony Guan
>Assignee: Karl Heinz Marbaise
>Priority: Minor
> Labels: performance
> Fix For: 3.5.3
>
>
> While investigating our internal builds (powered by Maven), I found that the
> in the maven target stats report, there is a big gap between the line of
> "Finished at ..." and "Final Memory...".
> Depending on the Java heap size, there were 15 seconds to 30 seconds gap in
> the two lines. (Your mileage may vary)
> Samples are (31 seconds below):
> 17:20:57.728 I [-@main] Finished at: 2017-10-26T17:20:57+00:00
> 17:21:28.105 I [-@main] Final Memory: 3352M/9102M
> Further investigation showed that the big gap lies in the System.gc() call in
> maven code:
> [https://github.com/apache/maven/blob/f5f76c70e1828a7e6c6267fc4bc53abc35c19ce7/maven-embedder/src/main/java/org/apache/maven/cli/event/ExecutionEventLogger.java]
> The problematic code is here:
> {code:java}
> private void logStats( MavenSession session )
> {
> infoLine( '-' );
> long finish = System.currentTimeMillis();
> long time = finish - session.getRequest().getStartTime().getTime();
> String wallClock = session.getRequest().getDegreeOfConcurrency() > 1 ? "
> (Wall Clock)" : "";
> logger.info( "Total time: " + formatDuration( time ) + wallClock );
> logger.info( "Finished at: " + formatTimestamp( finish ) );
> System.gc();
> Runtime r = Runtime.getRuntime();
> long mb = 1024 * 1024;
> logger.info( "Final Memory: " + ( r.totalMemory() - r.freeMemory() ) / mb +
> "M/" + r.totalMemory() / mb + "M" );
> }
> {code}
> It turns out that for each executed target, there is a Full GC invoked, just
> in order to get the memory summary. The intention may be good, so you can
> investigate the heap footprint. But this hurts performance in an accumulated
> way, and most users are not aware of this losing cpu cycles using Maven.
> Simple calculation for the cost of this coding: let's say Maven averages
> active N users, and these N users are using Maven to build everyday for T
> targets, then we have an estimate that N*T full GCs will be incurred everyday.
> These Full GCs average H hours, then N*T*H is the time wasted.
> Assuming they all use AWS for the builds, then it can be translated to money
> they have to pay to cloud providers unnecessary.
> So we should make this "memory stats after mvn target execution" disabled by
> default. Of course, it's better to provide a parameter to disable/enable this
> summary line for more flexibility.
> For current users, if you want to do something about this waste, the remedy
> is simple too: you can just add a JVM option -XX:+DisableExplicitGC from
> maven configuration.
>
--
This message was sent by Atlassian JIRA
(v7.6.3#76005)
[jira] [Commented] (MNG-6340) [Performance]To make System.gc() call configurable in target summary code
[
https://issues.apache.org/jira/browse/MNG-6340?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=16351842#comment-16351842
]
Karl Heinz Marbaise commented on MNG-6340:
--
The simplest solution I done to remove this call to {{System.gc()}} which is
not very useful.
> [Performance]To make System.gc() call configurable in target summary code
> -
>
> Key: MNG-6340
> URL: https://issues.apache.org/jira/browse/MNG-6340
> Project: Maven
> Issue Type: Improvement
> Components: Design, Patterns & Best Practices
>Affects Versions: 3.5.2
> Environment: Linux, AWS, OpenStack
>Reporter: Tony Guan
>Assignee: Karl Heinz Marbaise
>Priority: Major
> Labels: performance
> Fix For: 3.5.3
>
>
> While investigating our internal builds (powered by Maven), I found that the
> in the maven target stats report, there is a big gap between the line of
> "Finished at ..." and "Final Memory...".
> Depending on the Java heap size, there were 15 seconds to 30 seconds gap in
> the two lines. (Your mileage may vary)
> Samples are (31 seconds below):
> 17:20:57.728 I [-@main] Finished at: 2017-10-26T17:20:57+00:00
> 17:21:28.105 I [-@main] Final Memory: 3352M/9102M
> Further investigation showed that the big gap lies in the System.gc() call in
> maven code:
> [https://github.com/apache/maven/blob/f5f76c70e1828a7e6c6267fc4bc53abc35c19ce7/maven-embedder/src/main/java/org/apache/maven/cli/event/ExecutionEventLogger.java]
> The problematic code is here:
> {code:java}
> private void logStats( MavenSession session )
> {
> infoLine( '-' );
> long finish = System.currentTimeMillis();
> long time = finish - session.getRequest().getStartTime().getTime();
> String wallClock = session.getRequest().getDegreeOfConcurrency() > 1 ? "
> (Wall Clock)" : "";
> logger.info( "Total time: " + formatDuration( time ) + wallClock );
> logger.info( "Finished at: " + formatTimestamp( finish ) );
> System.gc();
> Runtime r = Runtime.getRuntime();
> long mb = 1024 * 1024;
> logger.info( "Final Memory: " + ( r.totalMemory() - r.freeMemory() ) / mb +
> "M/" + r.totalMemory() / mb + "M" );
> }
> {code}
> It turns out that for each executed target, there is a Full GC invoked, just
> in order to get the memory summary. The intention may be good, so you can
> investigate the heap footprint. But this hurts performance in an accumulated
> way, and most users are not aware of this losing cpu cycles using Maven.
> Simple calculation for the cost of this coding: let's say Maven averages
> active N users, and these N users are using Maven to build everyday for T
> targets, then we have an estimate that N*T full GCs will be incurred everyday.
> These Full GCs average H hours, then N*T*H is the time wasted.
> Assuming they all use AWS for the builds, then it can be translated to money
> they have to pay to cloud providers unnecessary.
> So we should make this "memory stats after mvn target execution" disabled by
> default. Of course, it's better to provide a parameter to disable/enable this
> summary line for more flexibility.
> For current users, if you want to do something about this waste, the remedy
> is simple too: you can just add a JVM option -XX:+DisableExplicitGC from
> maven configuration.
>
--
This message was sent by Atlassian JIRA
(v7.6.3#76005)
