How to time the different stages of maven executio

Question

I have a maven build that is extremely slow. I would like to know whether there is a way to profile maven execution in order to find out which are the most time-consuming steps.

Later I will want to compare these times between builds for older versions (which were faster), so they should be ideally in a format that can be compared/diffed/graphed.

Answer 1

i just create a gist here : https://gist.github.com/boly38/7316378

This is a sample example on how to log datetime of some maven lifecycle steps.

Of course you could adapt this sample to set your own output format (and graph it ...).

Hope this help

---

Extract :

        <profile>
            <id>stats</id>
            <build>
                <plugins>
                    <plugin>
                        <groupId>org.apache.maven.plugins</groupId>
                        <artifactId>maven-antrun-plugin</artifactId>
                        <executions>
                            <execution>
                                <id>log_validate</id>
                                <phase>validate</phase>
                                <goals><goal>run</goal></goals>
                                <configuration>
                                    <tasks>
                                        <tstamp><format property="stepTstamp" pattern="dd-HH:mm:ss" locale="en,US" /></tstamp>
                                        <echo file="stats.log" append="true"
                                              message="${line.separator}${line.separator}${stepTstamp} validate${line.separator}"/>
                                    </tasks>
                                </configuration>
                            </execution>
    (...)
                            <execution>
                                <id>log_process_sources</id>
                                <phase>process-sources</phase>
                                <goals><goal>run</goal></goals>
                                <configuration>
                                    <tasks>
                                        <tstamp><format property="stepTstamp" pattern="dd-HH:mm:ss" locale="en,US" /></tstamp>
                                        <echo file="stats.log" append="true"
                                              message="${stepTstamp} process-sources${line.separator}"/>
                                    </tasks>
                                </configuration>
                            </execution>
(...)

Answer 2

Out of the box solution is the takari maven profiler: https://github.com/takari/maven-profiler

Sample output from its page:

org.apache.maven:maven-core:3.1.2-SNAPSHOT

    clean 176ms
        org.apache.maven.plugins:maven-clean-plugin:2.5 (default-clean) 176ms

    initialize 408ms
        org.codehaus.mojo:buildnumber-maven-plugin:1.2 (create-noncanonicalrev) 349ms
        org.codehaus.mojo:buildnumber-maven-plugin:1.2 (create-buildnumber) 59ms

    generate-sources 408ms
        org.codehaus.modello:modello-maven-plugin:1.8.1 (standard) 369ms
        org.codehaus.modello:modello-maven-plugin:1.8.1 (standard) 28ms
        org.codehaus.modello:modello-maven-plugin:1.8.1 (standard) 11ms

    generate-resources 933ms
        org.apache.maven.plugins:maven-remote-resources-plugin:1.4 (default) 932ms

    process-resources 225ms
        org.apache.maven.plugins:maven-resources-plugin:2.6 (default-resources) 224ms

    compile 4s 522ms
        org.apache.maven.plugins:maven-compiler-plugin:2.5.1 (default-compile) 4s 522ms

    process-classes 6s 880ms
        org.codehaus.mojo:animal-sniffer-maven-plugin:1.6 (check-java-1.5-compat) 5s 814ms
        org.codehaus.plexus:plexus-component-metadata:1.5.5 (default) 946ms
        org.sonatype.plugins:sisu-maven-plugin:1.1 (default) 120ms

    process-test-resources 173ms
        org.apache.maven.plugins:maven-resources-plugin:2.6 (default-testResources) 173ms

    test-compile 818ms
        org.apache.maven.plugins:maven-compiler-plugin:2.5.1 (default-testCompile) 818ms

    process-test-classes 134ms
        org.codehaus.plexus:plexus-component-metadata:1.5.5 (default) 110ms
        org.sonatype.plugins:sisu-maven-plugin:1.1 (default) 23ms

    test 11s 306ms
        org.apache.maven.plugins:maven-surefire-plugin:2.12 (default-test) 11s 306ms

    package 1s 371ms
        org.apache.maven.plugins:maven-jar-plugin:2.4 (default-jar) 502ms
        org.apache.maven.plugins:maven-site-plugin:3.3 (attach-descriptor) 869ms

Answer 3

This functionality has been included in Maven3. Here's the associated ticket: https://issues.apache.org/jira/browse/MNG-4639

If you need to do the same with Maven2 I'd recommend building yor own plugin that is hooks into all phases of execution ( or just the ones you need to track).

Answer 4

https://github.com/jcgay/maven-profiler is a similar handy tool. It's easy to setup and use. (Having something like it or EventSpy takari/maven-profiler in core Maven as an option would certainly be neat; comment in https://issues.apache.org/jira/browse/MNG-4639 ..)

Answer 5

This is the quickest possible way:

export MAVEN_OPTS="-Dorg.slf4j.simpleLogger.dateTimeFormat=HH:mm:ss,SSS \
                   -Dorg.slf4j.simpleLogger.showDateTime=true" 
mvn test

Results in

MAVEN_OPTS="-Dorg.slf4j.simpleLogger.dateTimeFormat=HH:mm:ss,SSS -Dorg.slf4j.simpleLogger.showDateTime=true" mvn test
17:06:07,330 [INFO] Scanning for projects...
17:06:07,447 [INFO] 
17:06:07,447 [INFO] ------------------------------------------------------------------------
17:06:07,448 [INFO] Building bimble-server 0.0.1-SNAPSHOT
17:06:07,448 [INFO] ------------------------------------------------------------------------
17:06:07,747 [INFO] 
17:06:07,748 [INFO] --- maven-resources-plugin:2.6:resources (default-resources) @ bimble-server ---

Based on info from Stanley Hillner's blog: