Extremely slow archiving when changing between archiver 3.0.1 and 3.0.2

[Classe]

When switching to 3.x versions of maven-jar-plugin, maven-javadoc-plugin and maven-source-plugin. Generating jars become very slow, in current project its going from <10min build time to 3.5hours instead.
What I can see has changed is the plexus-archiver.
maven-jar-plugin: 2.9 to 3.1.1
maven-javadoc-plugin 2.5 to 3.6.0
maven-source-plugin 2.5 to 3.6.0

While doing a stackdump during jar or javadoc it seems to take up a lot of time in the plexus-archiver.
Stacktrace of where its spending a lot of time:

   java.lang.Thread.State: RUNNABLE
	at sun.nio.fs.UnixNativeDispatcher.getgrgid(java.base@11/Native Method)
	at sun.nio.fs.UnixUserPrincipals.fromGid(java.base@11/UnixUserPrincipals.java:129)
	at sun.nio.fs.UnixFileAttributes.group(java.base@11/UnixFileAttributes.java:208)
	- locked <0x000000062d663c90> (a sun.nio.fs.UnixFileAttributes)
	at sun.nio.fs.UnixFileAttributeViews$Posix.addRequestedPosixAttributes(java.base@11/UnixFileAttributeViews.java:214)
	at sun.nio.fs.UnixFileAttributeViews$Unix.readAttributes(java.base@11/UnixFileAttributeViews.java:362)
	at sun.nio.fs.AbstractFileSystemProvider.readAttributes(java.base@11/AbstractFileSystemProvider.java:94)
	at java.nio.file.Files.readAttributes(java.base@11/Files.java:1996)
	at org.codehaus.plexus.components.io.attributes.FileAttributes.<init>(FileAttributes.java:67)
	at org.codehaus.plexus.components.io.resources.PlexusIoFileResourceCollection.addResources(PlexusIoFileResourceCollection.java:156)
	at org.codehaus.plexus.components.io.resources.PlexusIoFileResourceCollection.getResources(PlexusIoFileResourceCollection.java:254)
	at org.codehaus.plexus.archiver.AbstractArchiver$1.hasNext(AbstractArchiver.java:506)
	at org.codehaus.plexus.archiver.zip.AbstractZipArchiver.createArchiveMain(AbstractZipArchiver.java:256)
	at org.codehaus.plexus.archiver.zip.AbstractZipArchiver.execute(AbstractZipArchiver.java:234)
	at org.codehaus.plexus.archiver.AbstractArchiver.createArchive(AbstractArchiver.java:987)
	at org.apache.maven.archiver.MavenArchiver.createArchive(MavenArchiver.java:649)
	at org.apache.maven.plugins.jar.AbstractJarMojo.createArchive(AbstractJarMojo.java:224)
	at org.apache.maven.plugins.jar.AbstractJarMojo.execute(AbstractJarMojo.java:255)
	at org.apache.maven.plugin.DefaultBuildPluginManager.executeMojo(DefaultBuildPluginManager.java:137)
	at org.apache.maven.lifecycle.internal.MojoExecutor.execute(MojoExecutor.java:208)
	at org.apache.maven.lifecycle.internal.MojoExecutor.execute(MojoExecutor.java:154)
	at org.apache.maven.lifecycle.internal.MojoExecutor.execute(MojoExecutor.java:146)
	at org.apache.maven.lifecycle.internal.LifecycleModuleBuilder.buildProject(LifecycleModuleBuilder.java:117)
	at org.apache.maven.lifecycle.internal.LifecycleModuleBuilder.buildProject(LifecycleModuleBuilder.java:81)
	at org.apache.maven.lifecycle.internal.builder.singlethreaded.SingleThreadedBuilder.build(SingleThreadedBuilder.java:56)
	at org.apache.maven.lifecycle.internal.LifecycleStarter.execute(LifecycleStarter.java:128)
	at org.apache.maven.DefaultMaven.doExecute(DefaultMaven.java:305)
	at org.apache.maven.DefaultMaven.doExecute(DefaultMaven.java:192)
	at org.apache.maven.DefaultMaven.execute(DefaultMaven.java:105)
	at org.apache.maven.cli.MavenCli.execute(MavenCli.java:954)
	at org.apache.maven.cli.MavenCli.doMain(MavenCli.java:288)
	at org.apache.maven.cli.MavenCli.main(MavenCli.java:192)
	at jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(java.base@11/Native Method)
	at jdk.internal.reflect.NativeMethodAccessorImpl.invoke(java.base@11/NativeMethodAccessorImpl.java:62)
	at jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(java.base@11/DelegatingMethodAccessorImpl.java:43)
	at java.lang.reflect.Method.invoke(java.base@11/Method.java:566)
	at org.codehaus.plexus.classworlds.launcher.Launcher.launchEnhanced(Launcher.java:289)
	at org.codehaus.plexus.classworlds.launcher.Launcher.launch(Launcher.java:229)
	at org.codehaus.plexus.classworlds.launcher.Launcher.mainWithExitCode(Launcher.java:415)
	at org.codehaus.plexus.classworlds.launcher.Launcher.main(Launcher.java:356)

[krosenvold]

I would suspect that there is some higher level change that is causing excessive reading of file attributes. So while this operation adds I/O it should be a very minor hit. You might also want to inspect the produced jar file to see that it does not contain surprising elements. I might suggest that you try all the archiver releases between 2.9 and 3.1.1 to see if it s possible to pinpoint whats causing it.

[Classe]

Sadly maven plugins aren't using any versions between 2.9 and 3.1.1.
I will take a look in differences in the jar

[Classe]

The produced jar looks exactly the same. No massive amount of files

[Classe]

Ive made a test with https://github.com/ThomasJaspers/java-junit-sample project.
I just added this in the pom.xml:

<build>
   <plugins>
     <plugin>
               <groupId>org.apache.maven.plugins</groupId>
               <artifactId>maven-javadoc-plugin</artifactId>
               <version>${maven.javadoc.plugin.version}</version>
               <executions>
                   <execution>
                       <id>attach-javadocs</id>
                       <goals>
                           <goal>jar</goal>
                       </goals>
                       <configuration>
                           <failOnError>false</failOnError>
                       </configuration>
                   </execution>
               </executions>
           </plugin>
           <plugin>
               <groupId>org.apache.maven.plugins</groupId>
               <artifactId>maven-source-plugin</artifactId>
               <version>${maven.source.plugin.version}</version>
               <executions>
                   <execution>
                       <id>attach-sources</id>
                       <goals>
                           <goal>jar</goal>
                       </goals>
                   </execution>
               </executions>
           </plugin>
<plugin>
               <groupId>org.apache.maven.plugins</groupId>
               <artifactId>maven-jar-plugin</artifactId>
               <version>${maven.jar.plugin.version}</version>
               <configuration>
                   <archive>
                       <index>true</index>
                       <manifest>
                           <addClasspath>true</addClasspath>
                       </manifest>
                   </archive>
               </configuration>
           </plugin>

  </plugins>
 </build>

with new versions of maven plugins I get:

<properties>
    <maven.compiler.source>1.8</maven.compiler.source>
    <maven.compiler.target>1.8</maven.compiler.target>
    <maven.source.plugin.version>3.0.0</maven.source.plugin.version>
    <maven.javadoc.plugin.version>3.0.1</maven.javadoc.plugin.version>
    <maven.jar.plugin.version>3.1.0</maven.jar.plugin.version>
  </properties> 

[INFO] Building jar: /test-project/target/my-app-1.0-SNAPSHOT-sources.jar
[INFO] ------------------------------------------------------------------------
[INFO] BUILD SUCCESS
[INFO] ------------------------------------------------------------------------
[INFO] Total time: 44.479 s
[INFO] Finished at: 2018-11-14T13:22:46+01:00
[INFO] Final Memory: 33M/597M
[INFO] ------------------------------------------------------------------------

and with old:

<properties>
    <maven.compiler.source>1.8</maven.compiler.source>
    <maven.compiler.target>1.8</maven.compiler.target>
    <maven.source.plugin.version>2.4</maven.source.plugin.version>
    <maven.javadoc.plugin.version>2.10.1</maven.javadoc.plugin.version>
    <maven.jar.plugin.version>2.6</maven.jar.plugin.version>
  </properties>

[INFO] ------------------------------------------------------------------------
[INFO] BUILD SUCCESS
[INFO] ------------------------------------------------------------------------
[INFO] Total time: 11.710 s
[INFO] Finished at: 2018-11-14T13:25:28+01:00
[INFO] Final Memory: 40M/482M
[INFO] ------------------------------------------------------------------------

[Classe]

Also some more input using maven-profiler:

Run package on 2018/11/14 13:55:19 with parameters: {maven.test.skip=true, profile=true, disableTimeSorting=true}
my-app (44.61 s)
Plugin execution Duration
org.apache.maven.plugins:maven-resources-plugin:2.6:resources {execution: default-resources} 889.8 ms
org.apache.maven.plugins:maven-compiler-plugin:3.1:compile {execution: default-compile} 1.402 s
org.apache.maven.plugins:maven-resources-plugin:2.6:testResources {execution: default-testResources} 2.019 ms
org.apache.maven.plugins:maven-compiler-plugin:3.1:testCompile {execution: default-testCompile} 1.383 ms
org.apache.maven.plugins:maven-surefire-plugin:2.18.1:test {execution: default-test} 480.9 ms
org.apache.maven.plugins:maven-jar-plugin**:3.1.0**:jar {execution: default-jar} 6.388 s
org.apache.maven.plugins:maven-javadoc-plugin**:3.0.1**:jar {execution: attach-javadocs} 21.25 s
org.apache.maven.plugins:maven-source-plugin:**3.0.0**:jar {execution: attach-sources} 11.33 s

my-app (11.86 s)

Run package on 2018/11/14 13:56:33 with parameters: {maven.test.skip=true, profile=true, disableTimeSorting=true}
my-app (11.37 s)
Plugin execution Duration
org.apache.maven.plugins:maven-resources-plugin:2.6:resources {execution: default-resources} 801.5 ms
org.apache.maven.plugins:maven-compiler-plugin:3.1:compile {execution: default-compile} 2.328 s
org.apache.maven.plugins:maven-resources-plugin:2.6:testResources {execution: default-testResources} 3.180 ms
org.apache.maven.plugins:maven-compiler-plugin:3.1:testCompile {execution: default-testCompile} 1.603 ms
org.apache.maven.plugins:maven-surefire-plugin:2.18.1:test {execution: default-test} 414.0 ms
org.apache.maven.plugins:maven-jar-plugin:**2.6**:jar {execution: default-jar} 1.892 s
org.apache.maven.plugins:maven-javadoc-plugin:**2.10.1**:jar {execution: attach-javadocs} 2.921 s
org.apache.maven.plugins:maven-source-plugin:**2.4**:jar {execution: attach-sources} 1.242 s

[plamentotev]

Hi,
I'll take a look at the example project you gave but meanwhile - do you think it can be related to #90 and codehaus-plexus/plexus-io#12

Now on second thought I don't think they are related.

[plamentotev]

I took a look at the example you provide but I cannot reproduce it. As a matter of fact on my system I see the opposite. The newer versions of the plugins are performing faster - about 28.8s vs about 29.5s in favor of the newer versions.

Can you share more details about your system - OS, Java version, file system, etc

[Classe]

It's RedHat 7 on a Virtual machine using Java 1.8.0_131-jce.
xfs (rw,relatime,attr2,inode64,noquota) local drive
Will do a test very soon with same Java version on Ubuntu 16.04

[Classe]

Seems its not present on Ubuntu 16.04 with same java version. Though disk on Ubuntu machine is local nvme and ext4.

[Classe]

If I do an strace -f -e open mvn package -Dmaven.test.skip=true I see a LOT more
open("/etc/group", O_RDONLY|O_CLOEXEC) = 141 in the newer versions (from 2529 to 40464), could this somehow be related? And that the redhat machine has a slower disk (/etc/group) with some security or something then the ubuntu machines.

Ive found out that /etc/group are handled in some other way on this RedHat setup. I think it does some lookups remote. And this makes it really slow with the new maven plugins which tends to access /etc/group more often

Why has the read of /etc/group increased this much?

[krosenvold]

@Classe You can override the version of plexus archiver used within the plugin by adding it as a dependency to the plugin.

@plamentotev Judging from memory, I seem to remember that there was some extremely subtle difference between the assumed duplicated files in #90. I would not write that off too quickly :)

[Classe]

Okay I nailed it down it happened between 3.0.1 and 3.0.2

[plamentotev]

@Classe would you please try to override plexus-archiver to 3.0.2 , org.codehaus.plexus:plexus-utils to 3.0.20 , org.codehaus.plexus:plexus-io to 2.6 and org.apache.commons:commons-compress to 1.9 . It is a long shot but I want to make sure that is not some of the dependencies that is the root cause,

[Classe]

codehaus-plexus/plexus-io@plexus-io-2.6...codehaus-plexus:plexus-io-2.6.1
stepping between these versions seems to be causing the issue