[jira] [Created] (MNG-6340) [Performance]To make System.gc() call configurable in target summary code

["Tony Guan (JIRA)" <ji...@apache.org>]

Tony Guan created MNG-6340:
------------------------------

             Summary: [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


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)