Extremely slow archiving when changing between archiver 3.0.1 and 3.0.2 #105

Classe · 2018-11-14T08:09:41Z

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)

The text was updated successfully, but these errors were encountered:

krosenvold · 2018-11-14T10:45:11Z

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 · 2018-11-14T11:22:05Z

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 · 2018-11-14T11:35:12Z

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

Classe · 2018-11-14T12:26:59Z

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 · 2018-11-14T13:00:40Z

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 · 2018-11-14T20:04:18Z

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 · 2018-11-14T20:35:46Z

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 · 2018-11-15T06:25:45Z

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 · 2018-11-15T06:31:10Z

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

Classe · 2018-11-15T08:05:49Z

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 · 2018-11-15T11:40:45Z

@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 · 2018-11-15T12:26:33Z

Okay I nailed it down it happened between 3.0.1 and 3.0.2

plamentotev · 2018-11-15T19:25:46Z

@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 · 2018-11-16T07:56:11Z

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

Classe · 2018-11-16T09:57:37Z

A guess is this change:
codehaus-plexus/plexus-io@104c7b0

Classe · 2018-11-16T11:55:36Z

Should I write defect in plexus-io and ref to this defect?

plamentotev · 2018-11-16T13:37:22Z

That would be nice, thank you. And nice find about the code that causes the issue.

…

On Fri, Nov 16, 2018, 13:55 Classe ***@***.*** wrote: Should I write defect in plexus-io and ref to this defect? — You are receiving this because you were mentioned. Reply to this email directly, view it on GitHub <#105 (comment)>, or mute the thread <https://github.com/notifications/unsubscribe-auth/AMLobTgY0BIav8J1Jj9Wkeq-5woH3UbMks5uvqe4gaJpZM4YdOGf> .

Classe · 2018-12-10T06:18:31Z

@plamentotev Could you up to next plexus-io version?

plamentotev · 2018-12-18T19:01:30Z

@Classe I plan to do a release this week. I'll update the plexus-io version as well.

Classe changed the title ~~Extremely slow archiving when changing between archiver 2.9 and 3.1.1~~ Extremely slow archiving when changing between archiver 3.0.1 and 3.0.2 Nov 15, 2018

Classe mentioned this issue Nov 16, 2018

Extremely slow archiving when changing between plexus-io 2.6 and 2.6.1 codehaus-plexus/plexus-io#16

Closed

plamentotev added the enhancement label Nov 25, 2018

plamentotev added this to the 3.7.1 milestone Nov 25, 2018

plamentotev closed this as completed in 91cad19 Dec 21, 2018

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Extremely slow archiving when changing between archiver 3.0.1 and 3.0.2 #105

Extremely slow archiving when changing between archiver 3.0.1 and 3.0.2 #105

Classe commented Nov 14, 2018

krosenvold commented Nov 14, 2018

Classe commented Nov 14, 2018 •

edited

Loading

Classe commented Nov 14, 2018

Classe commented Nov 14, 2018 •

edited

Loading

Classe commented Nov 14, 2018

plamentotev commented Nov 14, 2018 •

edited

Loading

plamentotev commented Nov 14, 2018 •

edited

Loading

Classe commented Nov 15, 2018

Classe commented Nov 15, 2018 •

edited

Loading

Classe commented Nov 15, 2018 •

edited

Loading

krosenvold commented Nov 15, 2018

Classe commented Nov 15, 2018

plamentotev commented Nov 15, 2018

Classe commented Nov 16, 2018

Classe commented Nov 16, 2018

Classe commented Nov 16, 2018

plamentotev commented Nov 16, 2018 via email

Classe commented Dec 10, 2018

plamentotev commented Dec 18, 2018

Extremely slow archiving when changing between archiver 3.0.1 and 3.0.2 #105

Extremely slow archiving when changing between archiver 3.0.1 and 3.0.2 #105

Comments

Classe commented Nov 14, 2018

krosenvold commented Nov 14, 2018

Classe commented Nov 14, 2018 • edited Loading

Classe commented Nov 14, 2018

Classe commented Nov 14, 2018 • edited Loading

Classe commented Nov 14, 2018

plamentotev commented Nov 14, 2018 • edited Loading

plamentotev commented Nov 14, 2018 • edited Loading

Classe commented Nov 15, 2018

Classe commented Nov 15, 2018 • edited Loading

Classe commented Nov 15, 2018 • edited Loading

krosenvold commented Nov 15, 2018

Classe commented Nov 15, 2018

plamentotev commented Nov 15, 2018

Classe commented Nov 16, 2018

Classe commented Nov 16, 2018

Classe commented Nov 16, 2018

plamentotev commented Nov 16, 2018 via email

Classe commented Dec 10, 2018

plamentotev commented Dec 18, 2018

Classe commented Nov 14, 2018 •

edited

Loading

Classe commented Nov 14, 2018 •

edited

Loading

plamentotev commented Nov 14, 2018 •

edited

Loading

plamentotev commented Nov 14, 2018 •

edited

Loading

Classe commented Nov 15, 2018 •

edited

Loading

Classe commented Nov 15, 2018 •

edited

Loading