39

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.

Carles Barrobés
  • 11,608
  • 5
  • 46
  • 60
  • I typically turn on relative time stamps in the maven log settings. This does not take much space from the messages and helps to see slow steps. org.slf4j.simpleLogger.showDateTime=true – eckes Jun 06 '17 at 22:14

5 Answers5

24

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 ---

If you then add that environment variable to your shell's config file (like ~/.bashrc or ~/.profile) you will have those timings every time you use Maven.

Based on info from Stanley Hillner's blog:

oligofren
  • 20,744
  • 16
  • 93
  • 180
6

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
Gábor Lipták
  • 9,646
  • 2
  • 59
  • 113
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 ..)

vorburger
  • 3,439
  • 32
  • 38
1

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).

Jakub Bochenski
  • 3,113
  • 4
  • 33
  • 61
Yuriy Nemtsov
  • 3,869
  • 4
  • 30
  • 44
  • yup, maven2. Any pointer to a starting point for this type of plugin? – Carles Barrobés Feb 25 '11 at 17:40
  • from your link I've seen that Hudson gives me that information, and it does indeed even for Maven 2, by checking "executed mojos" – Carles Barrobés Feb 25 '11 at 17:44
  • Oh, nice. I thought that Hudson/Jenkins needed maven3 support to be able to do this. – Yuriy Nemtsov Feb 25 '11 at 18:06
  • Nice indeed. Unfortunately the build times at the server differ from the ones at my local build machine direct maven execution... and I still can't time them there, where some "innocent" steps seem to take much longer than at the server – Carles Barrobés Feb 25 '11 at 21:19
  • @George: have you got some experience writing such kind of maven plugins? if you pass me the reference to some good tutorial doc, I'll finally accept your answer ;) – Carles Barrobés Mar 04 '11 at 22:02
  • Heh, start with the [plugin development guide](http://maven.apache.org/guides/plugin/guide-java-plugin-development.html). Then take a look at the [api specs](http://maven.apache.org/developers/mojo-api-specification.html) and [executing in multiple phases](http://stackoverflow.com/questions/1121373/multiple-antrun-tasks-in-maven). – Yuriy Nemtsov Mar 05 '11 at 19:47
  • 23
    @George, I'm confused by that ticket. It's still open and unassigned. When you say it's 'included in Maven3' what exactly does the end-user have to do? – artbristol Jun 10 '11 at 12:28
  • 1
    @artbristol, you are right. The functionality is obviously not included in Maven. You have to write your own AbstractExecutionListener or EventSpy. The EventSpy mentioned by Jason van Zyl there looks incomplete. Builds started with -T are not supported. – rwitzel Mar 18 '14 at 10:03
  • 1
    If anyone would like to use it for a Jenkins Maven Project -- be informed that you can't. Maven Core Extensions are not supported https://issues.jenkins-ci.org/browse/JENKINS-28629 – Jakub Bochenski Dec 07 '16 at 18:20
0

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>
(...)
boly38
  • 1,806
  • 24
  • 29