[ 
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)

Reply via email to