On 2018-04-13T21:48:58 +0200
Karl Heinz Marbaise <khmarba...@gmx.de> wrote:

> Hi Mark,

'Ello.

> On 13/04/18 21:20, Mark Raynsford wrote:
> 
> First it would be good to know which Maven version are you using? And on 
> which JDK you are running?

Hah, I purposefully left out details in the hope that it wouldn't be my
problem specifically. From the one second build you've described, it
appears that perhaps it might be.

My system:

Linux copperhead.int.arc7.info 4.15.14-1-ARCH #1 SMP PREEMPT Wed Mar 28
17:34:29 UTC 2018 x86_64 GNU/Linux

Intel(R) Core(TM) i5-2410M CPU @ 2.30GHz, 8GB ram.

openjdk version "9.0.4"
OpenJDK Runtime Environment (build 9.0.4+11)
OpenJDK 64-Bit Server VM (build 9.0.4+11, mixed mode)

Apache Maven 3.5.2 (NON-CANONICAL_2017-10-25T13:09:52+03:00_root;
2017-10-25T10:09:52Z) Maven home: /opt/maven
Java version: 9.0.4, vendor: Oracle Corporation
Java home: /usr/lib/jvm/java-9-openjdk
Default locale: en_GB, platform encoding: UTF-8
OS name: "linux", version: "4.15.14-1-arch", arch: "amd64", family:
"unix"

> Maybe I misunderstand you ...are you running it from plain command line 
> or from inside your IDE ?

The command line in the log is:

  mvn -Dmaven.tests.skip=true -DskipTests=true package

Although in the IDE in real projects, I'm skipping more plugin
executions than that.

> 
> What are you memory settings? How is your JDK configured ? Which command 
> line options ? (MAVEN_OPTS?):??

I'm both running it from the command line and from the IDE. My point
was that 16 seconds for a command line build is tolerable (although 
still pretty damn high for a project that only compiles one Java file 
and doesn't do anything else), but running the same build from within 
an IDE is painful (because in the IDE, I'm hoping for instant gratification
when I click "Run..." and I don't care about producing a full build
that someone else will use).

$ env | grep MAVEN
MAVEN_OPTS=-Xmx512m

My JDK is essentially unconfigured. Whatever the default settings are
for Linux AMD64, OpenJDK 9.

> Depending on your JVM and the configuration that can be quite large 
> different time on startup...there are several configurations which can 
> be used to improve that...

I'm open to suggestions. I'm fairly confident that it's not JVM startup
time that's the issue. For example, if I add the -X flag to Maven, you
can see that control reaches whatever passes for Maven's main() function
in roughly one second:

2018-04-13 21:00:01.455570500 
2018-04-13 21:00:02.740905500 Apache Maven 3.5.2 
(NON-CANONICAL_2017-10-25T13:09:52+03:00_root; 2017-10-25T10:09:52Z)
2018-04-13 21:00:02.741034500 Maven home: /opt/maven
2018-04-13 21:00:02.741192500 Java version: 9.0.4, vendor: Oracle Corporation
2018-04-13 21:00:02.741333500 Java home: /usr/lib/jvm/java-9-openjdk
2018-04-13 21:00:02.741454500 Default locale: en_GB, platform encoding: UTF-8
2018-04-13 21:00:02.741829500 OS name: "linux", version: "4.15.14-1-arch", 
arch: "amd64", family: "unix"
2018-04-13 21:00:06.841656500 [DEBUG] Created new class realm maven.api
2018-04-13 21:00:06.842724500 [DEBUG] Importing foreign packages into class 
realm maven.api
2018-04-13 21:00:06.844680500 [DEBUG]   Imported: javax.annotation.* < 
plexus.core
2018-04-13 21:00:06.847413500 [DEBUG]   Imported: javax.enterprise.inject.* < 
plexus.core
2018-04-13 21:00:06.847911500 [DEBUG]   Imported: javax.enterprise.util.* < 
plexus.core
2018-04-13 21:00:06.848473500 [DEBUG]   Imported: javax.inject.* < plexus.core
2018-04-13 21:00:06.849076500 [DEBUG]   Imported: org.apache.maven.* < 
plexus.core
2018-04-13 21:00:06.849575500 [DEBUG]   Imported: org.apache.maven.artifact < 
plexus.core
2018-04-13 21:00:06.850103500 [DEBUG]   Imported: org.apache.maven.classrealm < 
plexus.core
2018-04-13 21:00:06.850619500 [DEBUG]   Imported: org.apache.maven.cli < 
plexus.core
2018-04-13 21:00:06.851178500 [DEBUG]   Imported: 
org.apache.maven.configuration < plexus.core
2018-04-13 21:00:06.851678500 [DEBUG]   Imported: org.apache.maven.exception < 
plexus.core
2018-04-13 21:00:06.852183500 [DEBUG]   Imported: org.apache.maven.execution < 
plexus.core
2018-04-13 21:00:06.852685500 [DEBUG]   Imported: 
org.apache.maven.execution.scope < plexus.core
2018-04-13 21:00:06.853183500 [DEBUG]   Imported: org.apache.maven.lifecycle < 
plexus.core
2018-04-13 21:00:06.853653500 [DEBUG]   Imported: org.apache.maven.model < 
plexus.core
2018-04-13 21:00:06.854292500 [DEBUG]   Imported: org.apache.maven.monitor < 
plexus.core
2018-04-13 21:00:06.854777500 [DEBUG]   Imported: org.apache.maven.plugin < 
plexus.core
2018-04-13 21:00:06.855287500 [DEBUG]   Imported: org.apache.maven.profiles < 
plexus.core
2018-04-13 21:00:06.855786500 [DEBUG]   Imported: org.apache.maven.project < 
plexus.core
2018-04-13 21:00:06.856284500 [DEBUG]   Imported: org.apache.maven.reporting < 
plexus.core
2018-04-13 21:00:06.856757500 [DEBUG]   Imported: org.apache.maven.repository < 
plexus.core
2018-04-13 21:00:06.857291500 [DEBUG]   Imported: org.apache.maven.rtinfo < 
plexus.core
2018-04-13 21:00:06.857751500 [DEBUG]   Imported: org.apache.maven.settings < 
plexus.core
2018-04-13 21:00:06.858242500 [DEBUG]   Imported: org.apache.maven.toolchain < 
plexus.core
2018-04-13 21:00:06.858750500 [DEBUG]   Imported: org.apache.maven.usability < 
plexus.core
2018-04-13 21:00:06.859247500 [DEBUG]   Imported: org.apache.maven.wagon.* < 
plexus.core
2018-04-13 21:00:06.859817500 [DEBUG]   Imported: 
org.apache.maven.wagon.authentication < plexus.core
2018-04-13 21:00:06.860359500 [DEBUG]   Imported: 
org.apache.maven.wagon.authorization < plexus.core
2018-04-13 21:00:06.860882500 [DEBUG]   Imported: org.apache.maven.wagon.events 
< plexus.core
2018-04-13 21:00:06.861413500 [DEBUG]   Imported: 
org.apache.maven.wagon.observers < plexus.core
2018-04-13 21:00:06.861943500 [DEBUG]   Imported: org.apache.maven.wagon.proxy 
< plexus.core
2018-04-13 21:00:06.862494500 [DEBUG]   Imported: 
org.apache.maven.wagon.repository < plexus.core
2018-04-13 21:00:06.862991500 [DEBUG]   Imported: 
org.apache.maven.wagon.resource < plexus.core
2018-04-13 21:00:06.863587500 [DEBUG]   Imported: org.codehaus.classworlds < 
plexus.core
2018-04-13 21:00:06.864084500 [DEBUG]   Imported: org.codehaus.plexus.* < 
plexus.core
2018-04-13 21:00:06.864589500 [DEBUG]   Imported: 
org.codehaus.plexus.classworlds < plexus.core
2018-04-13 21:00:06.865246500 [DEBUG]   Imported: org.codehaus.plexus.component 
< plexus.core
2018-04-13 21:00:06.865785500 [DEBUG]   Imported: 
org.codehaus.plexus.configuration < plexus.core
2018-04-13 21:00:06.866347500 [DEBUG]   Imported: org.codehaus.plexus.container 
< plexus.core
2018-04-13 21:00:06.866863500 [DEBUG]   Imported: org.codehaus.plexus.context < 
plexus.core
2018-04-13 21:00:06.867389500 [DEBUG]   Imported: org.codehaus.plexus.lifecycle 
< plexus.core
2018-04-13 21:00:06.867877500 [DEBUG]   Imported: org.codehaus.plexus.logging < 
plexus.core
2018-04-13 21:00:06.868428500 [DEBUG]   Imported: 
org.codehaus.plexus.personality < plexus.core
2018-04-13 21:00:06.868969500 [DEBUG]   Imported: 
org.codehaus.plexus.util.xml.Xpp3Dom < plexus.core
2018-04-13 21:00:06.869528500 [DEBUG]   Imported: 
org.codehaus.plexus.util.xml.pull.XmlPullParser < plexus.core
2018-04-13 21:00:06.870156500 [DEBUG]   Imported: 
org.codehaus.plexus.util.xml.pull.XmlPullParserException < plexus.core
2018-04-13 21:00:06.870915500 [DEBUG]   Imported: 
org.codehaus.plexus.util.xml.pull.XmlSerializer < plexus.core
2018-04-13 21:00:06.871710500 [DEBUG]   Imported: org.eclipse.aether.* < 
plexus.core
2018-04-13 21:00:06.872369500 [DEBUG]   Imported: org.eclipse.aether.artifact < 
plexus.core
2018-04-13 21:00:06.872882500 [DEBUG]   Imported: org.eclipse.aether.collection 
< plexus.core
2018-04-13 21:00:06.873802500 [DEBUG]   Imported: org.eclipse.aether.deployment 
< plexus.core
2018-04-13 21:00:06.874304500 [DEBUG]   Imported: org.eclipse.aether.graph < 
plexus.core
2018-04-13 21:00:06.874690500 [DEBUG]   Imported: org.eclipse.aether.impl < 
plexus.core
2018-04-13 21:00:06.875170500 [DEBUG]   Imported: 
org.eclipse.aether.installation < plexus.core
2018-04-13 21:00:06.875679500 [DEBUG]   Imported: 
org.eclipse.aether.internal.impl < plexus.core
2018-04-13 21:00:06.876191500 [DEBUG]   Imported: org.eclipse.aether.metadata < 
plexus.core
2018-04-13 21:00:06.876668500 [DEBUG]   Imported: org.eclipse.aether.repository 
< plexus.core
2018-04-13 21:00:06.877151500 [DEBUG]   Imported: org.eclipse.aether.resolution 
< plexus.core
2018-04-13 21:00:06.877530500 [DEBUG]   Imported: org.eclipse.aether.spi < 
plexus.core
2018-04-13 21:00:06.877950500 [DEBUG]   Imported: org.eclipse.aether.transfer < 
plexus.core
2018-04-13 21:00:06.878354500 [DEBUG]   Imported: org.eclipse.aether.version < 
plexus.core
2018-04-13 21:00:06.878870500 [DEBUG]   Imported: org.fusesource.jansi.* < 
plexus.core
2018-04-13 21:00:06.879322500 [DEBUG]   Imported: org.slf4j.* < plexus.core
2018-04-13 21:00:06.879766500 [DEBUG]   Imported: org.slf4j.helpers.* < 
plexus.core
2018-04-13 21:00:06.880195500 [DEBUG]   Imported: org.slf4j.spi.* < plexus.core
2018-04-13 21:00:06.880859500 [DEBUG] Populating class realm maven.api
2018-04-13 21:00:07.210344500 [INFO] Error stacktraces are turned on.
2018-04-13 21:00:07.210806500 [DEBUG] Message scheme: color
2018-04-13 21:00:07.214240500 [DEBUG] Message styles: debug info warning error 
success failure strong mojo project
2018-04-13 21:00:07.236587500 [DEBUG] Reading global settings from 
/opt/maven/conf/settings.xml
2018-04-13 21:00:07.237263500 [DEBUG] Reading user settings from 
/home/someone/.m2/settings.xml
2018-04-13 21:00:07.343776500 [DEBUG] Reading global toolchains from 
/opt/maven/conf/toolchains.xml
2018-04-13 21:00:07.344127500 [DEBUG] Reading user toolchains from 
/home/someone/.m2/toolchains.xml
2018-04-13 21:00:07.381532500 [DEBUG] Using local repository at 
/home/someone/.m2/repository
2018-04-13 21:00:07.482942500 [DEBUG] Using manager 
EnhancedLocalRepositoryManager with priority 10.0 for 
/home/someone/.m2/repository
2018-04-13 21:00:07.528131500 [INFO] Scanning for projects...

You can see that it takes roughly a second to get as far as
printing the "Apache Maven 3.5.2..." message, and then takes 
about four seconds to get to "Created new class realm...". 
It's up to seven seconds before it even starts scanning for 
projects. The build then takes a good 5-7 seconds on top of
that. That equates to about twelve seconds minimum when I 
click "Run..." in an IDE, for a single-module build with
next to no plugins executing.

Are there options that can improve Maven's startup time?

The maven-buildtime-profiler plugin will definitely be useful
for larger builds, but right now I'm concerned about this
bit of overhead that appears to be present for even the most 
trivial of builds. I'm not sure the profiler will even see that
overhead as it happens before the profiler would have a chance 
to capture data.

-- 
Mark Raynsford | http://www.io7m.com

Attachment: pgppUNYzFq_kr.pgp
Description: OpenPGP digital signature

Reply via email to