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)
