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