Closed cstamas closed 2 years ago
cstamas
commented
2 years ago This seems mvnd related: building this one single module (using -f module/pom.xml) with mvn is 9sec but with mvnd is 2:26!!! Wild guess: most probably classpath/parent differences, but unsure why would sisu scan anything outside the realm it needs to scan (build output + deps, that is same for both -- verified using -X)
cstamas
commented
2 years ago Debug report of mvnd run (mvnd -f module/pom.xml -X):
[DEBUG] SUCCESS build of project com.walmartlabs.proximity.components:px-webapp
[DEBUG] Builder state: blocked=0 finished=1 ready-or-running=0
[DEBUG] Task segment [clean, install], number of projects 1
[INFO] Segment walltime 146 s, segment projects service time 146 s, effective/maximum degree of concurrency 1.00/11
[DEBUG] ------------------------------------------------------------------------
[DEBUG] Build Time Summary:
[DEBUG] ------------------------------------------------------------------------
[DEBUG] px-webapp [145.988s]
[DEBUG] maven-clean-plugin:clean (default-clean) ................. [0.100s]
[DEBUG] maven-enforcer-plugin:enforce (enforce-environment) ...... [0.096s]
[DEBUG] maven-enforcer-plugin:enforce (enforce-dependencies) ..... [0.060s]
[DEBUG] properties-maven-plugin:set-system-properties (default) .. [0.031s]
[DEBUG] buildnumber-maven-plugin:create (build-identity) ......... [0.298s]
[DEBUG] jacoco-maven-plugin:prepare-agent (pre-unit-test) ........ [0.067s]
[DEBUG] maven-resources-plugin:resources (default-resources) ..... [0.061s]
[DEBUG] maven-compiler-plugin:compile (default-compile) .......... [1.185s]
[DEBUG] sisu-maven-plugin:main-index (default) ................... [0.067s]
[DEBUG] maven-resources-plugin:testResources (default-testResource [0.004s]
[DEBUG] maven-compiler-plugin:testCompile (default-testCompile) .. [0.006s]
[DEBUG] sisu-maven-plugin:test-index (default) ................... [0.004s]
[DEBUG] maven-surefire-plugin:test (default-test) ................ [0.084s]
[DEBUG] sisu-maven-plugin:index (index) .......................... [138.772s]
[DEBUG] maven-jar-plugin:jar (default-jar) ....................... [0.171s]
[DEBUG] maven-source-plugin:jar-no-fork (default) ................ [0.157s]
[DEBUG] maven-assembly-plugin:single (lib) ....................... [3.518s]
[DEBUG] jacoco-maven-plugin:prepare-agent (pre-integration-test) . [0.003s]
[DEBUG] modernizer-maven-plugin:modernizer (modernizer) .......... [0.066s]
[DEBUG] maven-install-plugin:install (default-install) ........... [1.238s]
[DEBUG] ------------------------------------------------------------------------
[DEBUG] sisu-maven-plugin:index (index) .......................... [138.772s]
[DEBUG] sisu-maven-plugin:test-index (default) ................... [0.004s]
[DEBUG] modernizer-maven-plugin:modernizer (modernizer) .......... [0.066s]
[DEBUG] sisu-maven-plugin:main-index (default) ................... [0.067s]
[DEBUG] buildnumber-maven-plugin:create (build-identity) ......... [0.298s]
[DEBUG] maven-jar-plugin:jar (default-jar) ....................... [0.171s]
[DEBUG] maven-enforcer-plugin:enforce (enforce-environment) ...... [0.096s]
[DEBUG] jacoco-maven-plugin:prepare-agent (pre-unit-test) ........ [0.067s]
[DEBUG] maven-clean-plugin:clean (default-clean) ................. [0.100s]
[DEBUG] maven-surefire-plugin:test (default-test) ................ [0.084s]
[DEBUG] maven-enforcer-plugin:enforce (enforce-dependencies) ..... [0.060s]
[DEBUG] maven-assembly-plugin:single (lib) ....................... [3.518s]
[DEBUG] maven-install-plugin:install (default-install) ........... [1.238s]
[DEBUG] maven-compiler-plugin:testCompile (default-testCompile) .. [0.006s]
[DEBUG] maven-resources-plugin:testResources (default-testResource [0.004s]
[DEBUG] properties-maven-plugin:set-system-properties (default) .. [0.031s]
[DEBUG] maven-compiler-plugin:compile (default-compile) .......... [1.185s]
[DEBUG] jacoco-maven-plugin:prepare-agent (pre-integration-test) . [0.003s]
[DEBUG] maven-resources-plugin:resources (default-resources) ..... [0.061s]
[DEBUG] maven-source-plugin:jar-no-fork (default) ................ [0.157s]
[INFO] ------------------------------------------------------------------------
[INFO] BUILD SUCCESS
[INFO] ------------------------------------------------------------------------
[INFO] Total time: 02:26 min (Wall Clock)
[INFO] Finished at: 2021-12-10T17:01:43+01:00
[INFO] ------------------------------------------------------------------------Hm, subtle differences between the 3 executions (main-index, test-index that are both FAST and index that is SLOW):
[INFO] --- sisu-maven-plugin:0.3.5:main-index (default) @ px-webapp ---
[DEBUG] Dependency collection stats {ConflictMarker.analyzeTime=51649, ConflictMarker.markTime=26043, ConflictMarker.nodeCount=34, ConflictIdSorter.graphTime=12145, ConflictIdSorter.topsortTime=16188, ConflictIdSorter.conflictIdCount=15, ConflictIdSorter.conflictIdCycleCount=0, ConflictResolver.totalTime=164041, ConflictResolver.conflictItemCount=32, DefaultDependencyCollector.collectTime=17401118, DefaultDependencyCollector.transformTime=305132}
[DEBUG] org.eclipse.sisu:sisu-maven-plugin:jar:0.3.5
[DEBUG] org.eclipse.sisu:org.eclipse.sisu.inject:jar:0.3.5:compile
[DEBUG] org.slf4j:slf4j-nop:jar:1.6.4:compile
[DEBUG] org.slf4j:slf4j-api:jar:1.6.4:compile
[DEBUG] org.apache.maven:maven-plugin-api:jar:3.0:compile
[DEBUG] org.apache.maven:maven-model:jar:3.0:compile
[DEBUG] org.apache.maven:maven-artifact:jar:3.0:compile
[DEBUG] org.apache.maven.shared:maven-common-artifact-filters:jar:1.4:compile
[DEBUG] org.apache.maven:maven-project:jar:2.0.8:compile
[DEBUG] org.apache.maven:maven-settings:jar:2.0.8:compile
[DEBUG] org.apache.maven:maven-profile:jar:2.0.8:compile
[DEBUG] org.apache.maven:maven-artifact-manager:jar:2.0.8:compile
[DEBUG] org.apache.maven:maven-repository-metadata:jar:2.0.8:compile
[DEBUG] org.apache.maven:maven-plugin-registry:jar:2.0.8:compile
[DEBUG] org.codehaus.plexus:plexus-utils:jar:3.0.24:compile
[DEBUG] Created new class realm plugin>org.eclipse.sisu:sisu-maven-plugin:0.3.5
[DEBUG] Importing foreign packages into class realm plugin>org.eclipse.sisu:sisu-maven-plugin:0.3.5
[DEBUG] Imported: < maven.api
[DEBUG] Populating class realm plugin>org.eclipse.sisu:sisu-maven-plugin:0.3.5
[DEBUG] Included: org.eclipse.sisu:sisu-maven-plugin:jar:0.3.5
[DEBUG] Included: org.eclipse.sisu:org.eclipse.sisu.inject:jar:0.3.5
[DEBUG] Included: org.slf4j:slf4j-nop:jar:1.6.4
[DEBUG] Included: org.apache.maven.shared:maven-common-artifact-filters:jar:1.4
[DEBUG] Included: org.codehaus.plexus:plexus-utils:jar:3.0.24
[DEBUG] Configuring mojo org.eclipse.sisu:sisu-maven-plugin:0.3.5:main-index from plugin realm ClassRealm[plugin>org.eclipse.sisu:sisu-maven-plugin:0.3.5, parent: org.mvndaemon.mvnd.common.MavenDaemon$1@327471b5]
[DEBUG] Configuring mojo 'org.eclipse.sisu:sisu-maven-plugin:0.3.5:main-index' with basic configurator -->
[DEBUG] (f) project = MavenProject: com.walmartlabs.proximity.components:px-webapp:3.7.16-SNAPSHOT @ /home/cstamas/Worx/walmartlabs/proximity/components/px-webapp/pom.xml
[DEBUG] -- end configuration --
[INFO] --- sisu-maven-plugin:0.3.5:test-index (default) @ px-webapp ---
[DEBUG] Configuring mojo org.eclipse.sisu:sisu-maven-plugin:0.3.5:test-index from plugin realm ClassRealm[plugin>org.eclipse.sisu:sisu-maven-plugin:0.3.5, parent: org.mvndaemon.mvnd.common.MavenDaemon$1@327471b5]
[DEBUG] Configuring mojo 'org.eclipse.sisu:sisu-maven-plugin:0.3.5:test-index' with basic configurator -->
[DEBUG] (f) project = MavenProject: com.walmartlabs.proximity.components:px-webapp:3.7.16-SNAPSHOT @ /home/cstamas/Worx/walmartlabs/proximity/components/px-webapp/pom.xml
[DEBUG] -- end configuration --
[INFO] --- sisu-maven-plugin:0.3.5:index (index) @ px-webapp ---
[DEBUG] Configuring mojo org.eclipse.sisu:sisu-maven-plugin:0.3.5:index from plugin realm ClassRealm[plugin>org.eclipse.sisu:sisu-maven-plugin:0.3.5, parent: org.mvndaemon.mvnd.common.MavenDaemon$1@327471b5]
[DEBUG] Configuring mojo 'org.eclipse.sisu:sisu-maven-plugin:0.3.5:index' with basic configurator -->
[DEBUG] (f) excludeTransitive = false
[DEBUG] (f) includeDependencies = true
[DEBUG] (s) outputDirectory = /home/cstamas/Worx/walmartlabs/proximity/components/px-webapp/target/classes
[DEBUG] (s) project = MavenProject: com.walmartlabs.proximity.components:px-webapp:3.7.16-SNAPSHOT @ /home/cstamas/Worx/walmartlabs/proximity/components/px-webapp/pom.xml
[DEBUG] -- end configuration --Effective plugin config
<plugin>
<groupId>org.eclipse.sisu</groupId>
<artifactId>sisu-maven-plugin</artifactId>
<version>0.3.5</version>
<executions>
<execution>
<goals>
<goal>main-index</goal>
<goal>test-index</goal>
</goals>
</execution>
<execution>
<id>index</id>
<phase>prepare-package</phase>
<goals>
<goal>index</goal>
</goals>
</execution>
</executions>
</plugin>
mcculls
commented
2 years ago index scans the whole dependency graph, while main-index and test-index just scan the project
You usually only need need the index goal when packaging multiple dependencies into things like uber-jars or WARs.
You could build sisu-maven-plugin with extra logging to dump out the result of getIndexPath() - that should show the difference between mvn and mvnd - it might be that the default dependency filter needs tweaking for mvnd
cstamas
commented
2 years ago Am doing exactly that + a reproducer, thanks!
cstamas
commented
2 years ago Modified sisu-maven-plugin index mojo to dump both, indexPath and classPath. They are identical on mvn and mvnd on my testbed project. Next need to try and compare on real project, but I have a feeling they will be same as well. This feels as is more about classloader hierarchy...
cstamas
commented
2 years ago K, I think I am on good path, but this is def not sisu issue. Seems mvnd classpath gets "polluted"? And as daemon is "resident", it pollutes more and more. Will try when back at my desk with "real" project, but I managed to get sisu-index jump out to other mojo runs on my test project as well....
(as a sidenote: used takari maven-timeline to measure mojo execution using both, mvn and mvnd, and as I built sisu.mojos and maven itself with maven, the maven-timeline suddenly got applied to those too)
cstamas
commented
2 years ago FTR test project is here https://github.com/cstamas/sisu-index-test
used mvn/mvnd clean package to compare.
cstamas
commented
2 years ago Modified sisu-maven-plugin index mojo to dump both, indexPath and classPath. They are identical on mvn and mvnd on my testbed project. Next need to try and compare on real project, but I have a feeling they will be same as well. This feels as is more about classloader hierarchy...
Confirmed, by using patched sisu-maven-plugin on big project, mvn/mvnd ends up using same classPath/indexPath (168/167 elements), still build times for single module execution are 9 sec vs 2 minutes as 20 seconds... (@mcculls If you want, I could give build times in nanoseconds or day too, if it helps -- you can still use Google Unit Conversion :wink: )
cstamas
commented
2 years ago Found the culprit: mvnd daemon does this https://github.com/mvndaemon/mvnd/blob/master/common/src/main/java/org/mvndaemon/mvnd/common/MavenDaemon.java#L31
By doing same thing in mvn (well, in sisu index mojo), run grows to same 2:20 minutes in vanilla mvn too.
cstamas
commented
2 years ago This is not sisu issue at all, so closing it out
cstamas
commented
2 years ago @mcculls just to keep you in loop: turned out that sisu-maven-plugin:index mojo when run in mvnd is slowed down when there are signed JARs (like bouncycastle, reproducer now reproduces the 9sec vs 2:20 https://github.com/cstamas/sisu-index-test) due this line: https://github.com/mvndaemon/mvnd/blob/97c587c11383a67b5bd0ff8388bd94c694b91c1e/common/src/main/java/org/mvndaemon/mvnd/common/MavenDaemon.java#L29-L31
When building with vanilla maven (mvn 3.8.4), sisu-index:indexMojo of given module finishes (almost) instantly.
But when building with mvnd, it hangs for 1 if not more minute, causing whole build to stall (as other threads finish, and build stops on this one thread). Or maybe not "hangs", but stalls, uses 500% CPU, so it "does something", but the amount of work seems totally different between mvn/mvnd.
Also, mvn builds project in 1:27 (as reported by mvn) while mvnd builds project (due this hang) in 2:54.
Took several thread dumps during hang, and it seems execution IS in sisu mojo: