maven-issues mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From "Karl Heinz Marbaise (JIRA)" <j...@apache.org>
Subject [jira] [Closed] (MNG-6340) [Performance]To make System.gc() call configurable in target summary code
Date Sun, 04 Feb 2018 17:34:00 GMT

     [ https://issues.apache.org/jira/browse/MNG-6340?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel
]

Karl Heinz Marbaise closed MNG-6340.
------------------------------------
    Resolution: Fixed

Done in [99e66229aca82e12292d0e481d8e71158cc52ca4|https://git-wip-us.apache.org/repos/asf?p=maven.git;a=commitdiff;h=99e66229aca82e12292d0e481d8e71158cc52ca4]

> [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 &amp; Best Practices
>    Affects Versions: 3.5.2
>         Environment: Linux, AWS, OpenStack
>            Reporter: Tony Guan
>            Assignee: Karl Heinz Marbaise
>            Priority: Minor
>              Labels: performance
>             Fix For: 3.5.3
>
>
> 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)

Mime
View raw message