Maven
  1. Maven
  2. MNG-4639

Be able to profile a maven build

    Details

    • Type: New Feature New Feature
    • Status: Open Open
    • Priority: Major Major
    • Resolution: Unresolved
    • Affects Version/s: None
    • Component/s: None
    • Labels:
      None
    • Complexity:
      Intermediate
    • Number of attachments :
      1

      Description

      A common problem with builds is that they can become quite long to run. As it is a know anti-pattern for CI for example, one has the need to try and optimize their builds.

      The thing is: the current granularity isn't sufficiently precise. In fact, you only only the time spent to build each module. This is a good start, though.

      Maven currently displays something like the following (let's speak only about maven 3):

      [INFO] Reactor Summary:
      [INFO] ------------------------------------------------------------------------
      [INFO] p1 ........................ SUCCESS [1:12.938s]
      [INFO] p2 ........................ SUCCESS [5.750s]
      [INFO] p3 ........................ SUCCESS [3:58.488s]
      [INFO] p4 ........................ SUCCESS [24.437s]
      [INFO] p5 ........................ SUCCESS [1.563s]
      [INFO] ------------------------------------------------------------------------
      [INFO] ------------------------------------------------------------------------
      [INFO] BUILD SUCCESSFUL
      [INFO] ------------------------------------------------------------------------
      [INFO] Total time: 5 minutes 46 seconds

      What would be great would be adding an option that would higher the details. Something like A/analyze (-profile would be too close to -P/profile option) would add detailed analysis, would print something like.

      [INFO] Reactor Summary:
      [INFO] ------------------------------------------------------------------------
      [INFO] p1 ........................ SUCCESS [1:12.938s]
      clean:clean (somepkg.CleanMojo) : 10.3s
      compiler:compile (...) : 50s
      ...
      and so on

      I'm not very well aware the level of details maven 3 API could provide. So the printing above could become irrelevant. In this case, printing a dedicated html or so report might be a better choice.

      Cheers
      PS : Though I'm really not introduced into maven code, if you think it's not too complicated, I could try and contribute on this field if I'm given some hints or good starting points.

        Activity

        Hide
        Jerome Lacoste added a comment -

        For those who are interested in this feature:

        • hudson already does this for you (at least in the maven3 support). the time for the mojos is stored in the build.xml (Search for ExecutedMojo). There's also a per module page summary on hudson that will display time used per mojo
        • you can implement the same in maven by looking at
          http://maven.apache.org/ref/3.0.2/maven-core/apidocs/org/apache/maven/execution/AbstractExecutionListener.html. This is used in and ./maven-embedder/src/main/java/org/apache/maven/cli/ExecutionEventLogger.java and instantiated by maven-embedder/src/main/java/org/apache/maven/cli/MavenCli.java
          You might for example want to add a new 'profiling' option. Not to confuse with maven profiles..
        • if you are interested by the downloads time, you might want to look at ./maven-embedder/src/main/java/org/apache/maven/cli/AbstractMavenTransferListener.java
          but as downloads might happen in parallel, I am not sure you will get the information you want (i.e. user time spent waiting for download to complete)

        Hope that helps.

        Show
        Jerome Lacoste added a comment - For those who are interested in this feature: hudson already does this for you (at least in the maven3 support). the time for the mojos is stored in the build.xml (Search for ExecutedMojo). There's also a per module page summary on hudson that will display time used per mojo you can implement the same in maven by looking at http://maven.apache.org/ref/3.0.2/maven-core/apidocs/org/apache/maven/execution/AbstractExecutionListener.html . This is used in and ./maven-embedder/src/main/java/org/apache/maven/cli/ExecutionEventLogger.java and instantiated by maven-embedder/src/main/java/org/apache/maven/cli/MavenCli.java You might for example want to add a new 'profiling' option. Not to confuse with maven profiles.. if you are interested by the downloads time, you might want to look at ./maven-embedder/src/main/java/org/apache/maven/cli/AbstractMavenTransferListener.java but as downloads might happen in parallel, I am not sure you will get the information you want (i.e. user time spent waiting for download to complete) Hope that helps.
        Hide
        Alexander Klimetschek added a comment -

        I implemented this - see attached patch or the diff in my github maven fork.

        Output looks like this at the end of the build (running "mvn -a install" for maven itself):

        [INFO] ------------------------------------------------------------------------
        [INFO] BUILD SUCCESS
        [INFO] ------------------------------------------------------------------------
        [INFO] Total time: 1:55.148s
        [INFO] Finished at: Tue Mar 19 15:50:33 CET 2013
        [INFO] Final Memory: 29M/102M
        [INFO] ------------------------------------------------------------------------
        [INFO] MOJO EXECUTION TIMES
        [INFO] ------------------------------------------------------------------------
        [INFO]  35% maven-surefire-plugin [40.74s]
        [INFO]      * test
        [INFO]  23% animal-sniffer-maven-plugin [27.65s]
        [INFO]      * check
        [INFO]  13% project setup [15.85s]
        [INFO]   7% maven-assembly-plugin [8.83s]
        [INFO]      * single
        [INFO]   4% maven-jar-plugin [4.86s]
        [INFO]      * jar
        [INFO]   3% maven-compiler-plugin [4.21s]
        [INFO]      * compile 3% [4.10s]
        [INFO]      * testCompile 0% [0.11s]
        [INFO]   3% maven-remote-resources-plugin [4.12s]
        [INFO]      * process
        [INFO]   3% plexus-component-metadata [3.49s]
        [INFO]      * generate-metadata 2% [2.65s]
        [INFO]      * generate-test-metadata 0% [0.85s]
        [INFO]   1% modello-maven-plugin [1.56s]
        [INFO]      * java 0% [1.13s]
        [INFO]      * xpp3-reader 0% [0.20s]
        [INFO]      * xpp3-writer 0% [0.15s]
        [INFO]      * xpp3-extended-reader 0% [0.08s]
        [INFO]   0% maven-site-plugin [1.10s]
        [INFO]      * attach-descriptor
        [INFO]   0% other [0.78s]
        [INFO]   0% maven-resources-plugin [0.71s]
        [INFO]      * resources 0% [0.45s]
        [INFO]      * testResources 0% [0.25s]
        [INFO]   0% scanning for projects [0.71s]
        [INFO]   0% buildnumber-maven-plugin [0.61s]
        [INFO]      * create-timestamp 0% [0.39s]
        [INFO]      * create 0% [0.22s]
        [INFO]   0% maven-install-plugin [0.35s]
        [INFO]      * install
        [INFO] ------------------------------------------------------------------------
        

        Details from the commit message:

        • adds new option "-a / --analyze" to the maven cli
        • which will profile mojo executions and output their time and percentage of total time sorted at the end of the build
        • groups by maven plugin and shows measurements split up by plugin goals
        • also measures project discovery ("scanning"), project setup time before first mojo ("project setup") and anything else ("other")
        • implemented in a special ExecutionListener called ProfilingExecutionListener
        • which is chained with the normal ExecutionEventLogger by a new ExecutionListenerChain helper that forwards the events to multiple listeners

        WDYT?

        Show
        Alexander Klimetschek added a comment - I implemented this - see attached patch or the diff in my github maven fork . Output looks like this at the end of the build (running "mvn -a install" for maven itself): [INFO] ------------------------------------------------------------------------ [INFO] BUILD SUCCESS [INFO] ------------------------------------------------------------------------ [INFO] Total time: 1:55.148s [INFO] Finished at: Tue Mar 19 15:50:33 CET 2013 [INFO] Final Memory: 29M/102M [INFO] ------------------------------------------------------------------------ [INFO] MOJO EXECUTION TIMES [INFO] ------------------------------------------------------------------------ [INFO] 35% maven-surefire-plugin [40.74s] [INFO] * test [INFO] 23% animal-sniffer-maven-plugin [27.65s] [INFO] * check [INFO] 13% project setup [15.85s] [INFO] 7% maven-assembly-plugin [8.83s] [INFO] * single [INFO] 4% maven-jar-plugin [4.86s] [INFO] * jar [INFO] 3% maven-compiler-plugin [4.21s] [INFO] * compile 3% [4.10s] [INFO] * testCompile 0% [0.11s] [INFO] 3% maven-remote-resources-plugin [4.12s] [INFO] * process [INFO] 3% plexus-component-metadata [3.49s] [INFO] * generate-metadata 2% [2.65s] [INFO] * generate-test-metadata 0% [0.85s] [INFO] 1% modello-maven-plugin [1.56s] [INFO] * java 0% [1.13s] [INFO] * xpp3-reader 0% [0.20s] [INFO] * xpp3-writer 0% [0.15s] [INFO] * xpp3-extended-reader 0% [0.08s] [INFO] 0% maven-site-plugin [1.10s] [INFO] * attach-descriptor [INFO] 0% other [0.78s] [INFO] 0% maven-resources-plugin [0.71s] [INFO] * resources 0% [0.45s] [INFO] * testResources 0% [0.25s] [INFO] 0% scanning for projects [0.71s] [INFO] 0% buildnumber-maven-plugin [0.61s] [INFO] * create-timestamp 0% [0.39s] [INFO] * create 0% [0.22s] [INFO] 0% maven-install-plugin [0.35s] [INFO] * install [INFO] ------------------------------------------------------------------------ Details from the commit message: adds new option "-a / --analyze" to the maven cli which will profile mojo executions and output their time and percentage of total time sorted at the end of the build groups by maven plugin and shows measurements split up by plugin goals also measures project discovery ("scanning"), project setup time before first mojo ("project setup") and anything else ("other") implemented in a special ExecutionListener called ProfilingExecutionListener which is chained with the normal ExecutionEventLogger by a new ExecutionListenerChain helper that forwards the events to multiple listeners WDYT?
        Hide
        Rod Woo added a comment -

        Another option is EventSpy. EventSpy is a standard way to extend Maven so you can use it with Jenkins/Hudson and so on.

        Use-Dmaven.ext.class.path=... or <maven>/lib/ext/<yours>.jar to let Maven know that you provided an extension.

        You can easily take the code of Alexander Klimetschek and make an EventSpy out of it.

        Show
        Rod Woo added a comment - Another option is EventSpy. EventSpy is a standard way to extend Maven so you can use it with Jenkins/Hudson and so on. Use-Dmaven.ext.class.path=... or <maven>/lib/ext/<yours>.jar to let Maven know that you provided an extension. You can easily take the code of Alexander Klimetschek and make an EventSpy out of it.
        Hide
        Jason van Zyl added a comment -

        Here is an event spy implementation:

        https://github.com/takari/maven-profiler

        Show
        Jason van Zyl added a comment - Here is an event spy implementation: https://github.com/takari/maven-profiler

          People

          • Assignee:
            Unassigned
            Reporter:
            Baptiste MATHUS
          • Votes:
            21 Vote for this issue
            Watchers:
            17 Start watching this issue

            Dates

            • Created:
              Updated: