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

• Type: Improvement
• Status: Closed
• Priority: Minor
• Resolution: Fixed
• Affects Version/s: 3.5.2
• Fix Version/s: 3.5.3
• Component/s: Design, Patterns & Best Practices
• Labels: performance
• Environment: Linux, AWS, OpenStack
• Assignee: Karl Heinz Marbaise
• Reporter: Tony Guan
• Created: 16/Jan/18 20:02
• Updated: 28/Mar/20 15:02
• Resolved: 04/Feb/18 17:33

Description

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:

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" );
}

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.