[jira] [Comment Edited] (MNG-7677) Maven 3.9.0 is ~10% slower than 3.8.7 in large multi-module builds

["Tamas Cservenak (Jira)" <ji...@apache.org>]

    [ https://issues.apache.org/jira/browse/MNG-7677?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=17685298#comment-17685298 ] 

Tamas Cservenak edited comment on MNG-7677 at 2/7/23 1:17 PM:
--------------------------------------------------------------

Can confirm these findings (using same Quarkus project and {{mvn validate -P quickbuild}} command line):
 * 3.8.7: 23.803sec
 * 3.9.0: 28.521sec
 * 3.9.0 w/ BF: 30.5.0.7sec
 * 3.9.1-SNAPSHOT w/ patch: 25.201sec
 * 3.9.1-SNAPSHOT w/ patch w/ BF: 27.204sec

This is the "patch" (just shaved off all "sus" things):  [https://gist.github.com/cstamas/2c0955ae83bb2132424b5b8f21715daf]


was (Author: cstamas):
Can confirm these findings (using same Quarkus project and {{mvn validate -P quickbuild}} command line):
 * 3.8.7: 23.803sec
 * 3.9.0: 28.521sec
 * 3.9.1-SNAPSHOT w/ patch: 25.201sec
 * 3.9.1-SNAPSHOT w/ patch w/ BF: 27.204sec

This is the "patch" (just shaved off all "sus" things):  https://gist.github.com/cstamas/2c0955ae83bb2132424b5b8f21715daf

> Maven 3.9.0 is ~10% slower than 3.8.7 in large multi-module builds
> ------------------------------------------------------------------
>
>                 Key: MNG-7677
>                 URL: https://issues.apache.org/jira/browse/MNG-7677
>             Project: Maven
>          Issue Type: Bug
>          Components: Performance
>    Affects Versions: 3.9.0
>            Reporter: Petr Široký
>            Priority: Minor
>         Attachments: profile-alloc-mvn-validate-3.8.7.html, profile-alloc-mvn-validate-3.9.0.html, profile-cpu-mvn-validate-3.8.7.html, profile-cpu-mvn-validate-3.9.0.html, profile-method-DefaultArtifact._init_-3.8.7.html, profile-method-DefaultArtifact._init_-3.9.0.html, profile-method-DefaultArtifact._init_-3.9.1-SNAPSHOT-reverted-PR166.html
>
>
> When testing the upcoming [Maven release 3.9.0|https://repository.apache.org/content/repositories/maven-1862/org/apache/maven/apache-maven/3.9.0/apache-maven-3.9.0-bin.tar.gz] I noticed the builds for large multi-module projects are somewhat slower.
> I was mainly using the [Quarkus projects|https://github.com/quarkusio/quarkus], which has more than 1k modules. I was specifically bulding the {{2.16.1.Final}} tag. Below are the numbers I got.
> *First batch:*
> {code:java}
> MAVEN_OPTS="-XX:+UseParallelGC -Xms2g -Xmx2g"{code}
> ||Maven cmd||Build time - Maven 3.8.7||Build time - Maven 3.9.0||
> |clean|2.9s|3.2s|
> |validate|02:17min|02:34min|
> |validate -T8|29s|33s|
> |validate -Dversion.enforcer.plugin=3.2.1|29s|40s|
> |validate -Dversion.enforcer.plugin=3.2.1 -T8|9s|14s|
> *Second batch (bigger heap):*
> {code:java}
> MAVEN_OPTS="-XX:+UseParallelGC -Xms5g -Xmx5g"{code}
> ||Maven cmd||Build time - Maven 3.8.7||Build time - Maven 3.9.0||
> |clean|2.9s|3.2s|
> |validate|02:11min|02:22min|
> |validate -T8|25s|28s|
> |validate -Dversion.enforcer.plugin=3.2.1|29s|35s|
> |validate -Dversion.enforcer.plugin=3.2.1 -T8|9s|11s|
> |install -DskipTests -Dversion.enforcer.plugin=3.2.1 -T8|01:49min|01:55min|
> *Notes:*
>  * The numbers are taken from the Maven output (the Wall Clock time). When testing with the time utility, the "real" execution time is about 0.6s longer (the time JVM needs to start-up). The values in the tables are averages over several runs (3 to 10 depending on the time the specific run actually took).
>  * All builds were run on Linux x64 (kernel 6.1.8) with JDK 19.0.1
>  * HW used during testing: AMD Ryzen 5800x (8 physical cores), 32GB RAM and SSD Samsung 980 Pro 1TB (these should not really matter for the comparison itself, but I am including it for completeness)
>  * Using {{ParallelGC}} since it should be the one with highest throughput (at the cost of longer pause times, which I don't really care about for Maven builds). Quick comparison with {{G1GC}} shows the builds are slightly faster, but it is almost negligible.
> There has already been some discussion regarding this in this older merged PR [https://github.com/apache/maven-resolver/pull/166] (which may be the cause behind the slowdown).
> See the attachments for CPU / allocation profiles (flame graphs), running {{mvn validate}} with both 3.8.7 and 3.9.0.
> *My analysis of the attached CPU / allocation profiles:*
> I was mainly looking at the differences in those two profiles (3.8.7 vs 3.9.0), not at the absolute numbers. There are possibly other places that could use some optimization, but that is outside of scope for this one.
> Both CPU and allocation profiles show that the CPU time / allocations increased the most in a code which seems to be doing some sort of dependency resolution, ultimately boiling down to a call to {{{}org.eclipse.aether.internal.impl.DefaultRepositorySystem.collectDependencies{}}}. The flame graphs show a bit different method calls inside Aether (maven-resolver), mainly because there are some structural changes (e.g. different class names) to the Aether dependency resolution between {{maven-resolver-1.6.3}} (used in {{{}3.8.7{}}}) and {{maven-resolver-1.9.4}} (used in {{{}3.9.0{}}}). The dependency resolution algorithm should be the same though (or at least as far as I can tell).
> Digging further down, the biggest difference seems to be in the number of calls to {{{}org.eclipse.aether.artifact.DefaultArtifact.<init>{}}}. The constructor includes merging two property maps together, which results in quite some work (CPU) and lots of garbage (HashMap$Node, etc).
> With the above assumption, I went on to profile the number of method (constructor) calls to {{org.eclipse.aether.artifact.DefaultArtifact.<init>}} (see the attachments profile-method-DefaultArtifact._init_-(3.8.7|3.9.0).html). The absolute numbers say that Maven 3.8.7 allocated ~9mil of these objects, while Maven 3.9.0 allocated ~26mil instances. That is about 3x times as much. When drilling down to the method {{org.eclipse.aether.internal.impl.DefaultRepositorySystem.collectDependencies}} and summing all the instances (there are three), we get ~2mil for instances for Maven 3.8.7 and ~19mil instances for Maven 3.9.0. Even if this would not be the root cause the "slowness" I am seeing, it is definitely something to look at.
> After some further digging in the -Aether- maven-resolver code I found the already mentioned change done in PR [https://github.com/apache/maven-resolver/pull/166]. It basically replaces strong reference to {{org.eclipse.aether.artifact.DefaultArtifact.<init>}} with a weak reference, which likely means the instances are cleaned-up much faster, and next time they are needed they must be constructed from scratch again. The change basically trades lower memory consumption for higher CPU usage (and more garbage). 
> I then tried to revert the change in https://github.com/apache/maven-resolver/pull/166, build maven-resolver 1.9.5-SNAPSHOT, update the resolver in maven-3.9.x branch and build from that. With this change reverted, I am basically seeing the same numbers as with Maven 3.8.7. Running the method profiling for {{org.eclipse.aether.artifact.DefaultArtifact.<init>}} with the updated Maven also shows the number of instances is back ~9mil as with Maven 3.8.7. Thus, at this point, I believe the change in https://github.com/apache/maven-resolver/pull/166 is the root behind the "slowness". If the change itself should remain, then we should probably take another look at how to better cache the instances. 
>  



--
This message was sent by Atlassian Jira
(v8.20.10#820010)