[
https://issues.apache.org/jira/browse/MNG-6340?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel
]
Karl Heinz Marbaise reassigned MNG-6340:
----------------------------------------
Assignee: Karl Heinz Marbaise
> [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
>
> 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)
