BuildTimeProfiler.java

  1. package com.soebes.maven.extensions;

  3. /*
  4.  * Licensed to the Apache Software Foundation (ASF) under one
  5.  * or more contributor license agreements.  See the NOTICE file
  6.  * distributed with this work for additional information
  7.  * regarding copyright ownership.  The ASF licenses this file
  8.  * to you under the Apache License, Version 2.0 (the
  9.  * "License"); you may not use this file except in compliance
  10.  * with the License.  You may obtain a copy of the License at
  11.  *
  12.  *   http://www.apache.org/licenses/LICENSE-2.0
  13.  *
  14.  * Unless required by applicable law or agreed to in writing,
  15.  * software distributed under the License is distributed on an
  16.  * "AS IS" BASIS, WITHOUT WARRANTIES OR CONDITIONS OF ANY
  17.  * KIND, either express or implied.  See the License for the
  18.  * specific language governing permissions and limitations
  19.  * under the License.
  20.  */

  22. import com.soebes.maven.extensions.artifact.DeployTimer;
  23. import com.soebes.maven.extensions.artifact.DownloadTimer;
  24. import com.soebes.maven.extensions.artifact.InstallTimer;
  25. import com.soebes.maven.extensions.metadata.MetadataDeploymentTimer;
  26. import com.soebes.maven.extensions.metadata.MetadataDownloadTimer;
  27. import com.soebes.maven.extensions.metadata.MetadataInstallTimer;
  28. import org.apache.maven.execution.ExecutionEvent;
  29. import org.apache.maven.execution.MavenExecutionRequest;
  30. import org.apache.maven.execution.MavenExecutionResult;
  31. import org.apache.maven.project.DependencyResolutionRequest;
  32. import org.apache.maven.project.DependencyResolutionResult;
  33. import org.apache.maven.project.MavenProject;
  34. import org.eclipse.aether.RepositoryEvent;
  35. import org.slf4j.Logger;
  36. import org.slf4j.LoggerFactory;

  38. import javax.inject.Named;
  39. import javax.inject.Singleton;
  40. import java.util.Collections;
  41. import java.util.LinkedList;
  42. import java.util.List;
  43. import java.util.Map;
  44. import java.util.Map.Entry;

  46. /**
  47.  * @author Karl Heinz Marbaise <a href="mailto:kama@soebes.de">kama@soebes.de</a>
  48.  */
  49. @Named
  50. @Singleton
  51. public class BuildTimeProfiler
  52.     extends LifeCycleOrdering
  53. {
  54.     private static final String SEPARATION_LINE = "------------------------------------------------------------------------";

  56.     private static final Logger LOGGER = LoggerFactory.getLogger(BuildTimeProfiler.class);

  58.     private final List<String> lifeCyclePhases;

  60.     private final DiscoveryTimer discoveryTimer;

  62.     private final GoalTimer goalTimer;

  64.     private final MojoTimer mojoTimer;

  66.     private final ProjectTimer projectTimer;

  68.     private final SessionTimer sessionTimer;

  70.     private final InstallTimer installTimer;

  72.     private final DeployTimer deployTimer;

  74.     private final DownloadTimer downloadTimer;

  76.     private final MetadataDownloadTimer metadataDownloadTimer;

  78.     private final MetadataDeploymentTimer metadataDeploymentTimer;

  80.     private final MetadataInstallTimer metadataInstallTimer;

  82.     private final ForkTimer forkTimer;

  84.     private final ProjectTimer forkProject;

  86.     private boolean activated;

  88.     public BuildTimeProfiler()
  89.     {
  90.         LOGGER.debug( "LifeCycleProfiler ctor called." );
  91.         this.lifeCyclePhases = Collections.synchronizedList(new LinkedList<>() );
  92.         this.discoveryTimer = new DiscoveryTimer();
  93.         this.goalTimer = new GoalTimer();
  94.         this.mojoTimer = new MojoTimer();
  95.         this.projectTimer = new ProjectTimer();
  96.         this.sessionTimer = new SessionTimer();
  97.         this.installTimer = new InstallTimer();
  98.         this.deployTimer = new DeployTimer();
  99.         this.downloadTimer = new DownloadTimer();

  101.         this.metadataDownloadTimer = new MetadataDownloadTimer();
  102.         this.metadataDeploymentTimer = new MetadataDeploymentTimer();
  103.         this.metadataInstallTimer = new MetadataInstallTimer();
  104.         this.forkTimer = new ForkTimer();
  105.         this.forkProject = new ProjectTimer();

  107.         String disabled = System.getProperty("maven-build-time-profiler.disabled", "unknown");
  108.         LOGGER.debug("MBTP: maven-build-time-profiler.disabled {}", disabled);
  109.         this.activated = !disabled.equals("true");
  110.     }

  112.     @Override
  113.     public void init( Context context )
  114.         throws Exception
  115.     {
  116.         super.init( context );

  118.         LOGGER.info( "Maven Build Time Profiler started. (Version {})", BuildTimeProfilerVersion.getVersion() );
  119.         if ( !activated ) {
  120.             LOGGER.info("Maven Build Time Profiler deactivated.");
  121.             return;
  122.         }

  124.         // Is this always in the context? Based on Maven Core yes.
  125.         String workingDirectory = (String) context.getData().get( "workingDirectory" );
  126.         LOGGER.debug( "MBTP: workingDirectory: {}", workingDirectory );

  128.         String multiModuleProjectDirectory = (String) context.getData().get( "multiModuleProjectDirectory" );
  129.         LOGGER.debug( "MBTP: multiModuleProjectDirectory: {}", multiModuleProjectDirectory );
  130.     }

  132.     @Override
  133.     public void onEvent( Object event )
  134.         throws Exception
  135.     {
  136.         try
  137.         {
  138.             if ( !activated ) {
  139.                 return;
  140.             }

  142.             if ( event instanceof ExecutionEvent)
  143.             {
  144.                 executionEventHandler( (ExecutionEvent) event );
  145.             }
  146.             else if ( event instanceof org.eclipse.aether.RepositoryEvent )
  147.             {
  148.                 repositoryEventHandler( (RepositoryEvent) event );
  149.             }
  150.             else if ( event instanceof MavenExecutionRequest)
  151.             {
  152.                 executionRequestEventHandler( (MavenExecutionRequest) event );
  153.             }
  154.             else if ( event instanceof MavenExecutionResult)
  155.             {
  156.                 executionResultEventHandler( (MavenExecutionResult) event );
  157.             }
  158.             else if ( event instanceof DependencyResolutionRequest)
  159.             {
  160.                 dependencyResolutionRequest( (DependencyResolutionRequest) event );
  161.             }
  162.             else if ( event instanceof DependencyResolutionResult)
  163.             {
  164.                 dependencyResolutionResult( (DependencyResolutionResult) event );
  165.             }
  166.             // The following event type is available since Maven 3.3.1+
  167.             // else if ( event instanceof DefaultSettingsBuildingRequest) {
  168.             // DefaultSettingsBuildingRequest r = null;
  169.             // r.getGlobalSettingsFile();
  170.             // r.getGlobalSettingsSource();
  171.             // r.getSystemProperties();
  172.             // r.getUserSettingsFile();
  173.             // r.getUserSettingsSource();
  174.             //
  175.             // r.setGlobalSettingsFile( globalSettingsFile );
  176.             // r.setGlobalSettingsSource( globalSettingsSource );
  177.             // r.setSystemProperties( systemProperties );
  178.             // r.setUserProperties( userProperties );
  179.             // r.setUserSettingsFile( userSettingsFile );
  180.             // r.setUserSettingsSource( userSettingsSource );
  181.             // }
  182.             // The following event type is available since Maven 3.3.1+
  183.             // else if (event instanceof DefaultSettingsBuildingRequest) {
  184.             //
  185.             // DefaultSettingsBuildingRequest r = null;
  186.             // r.getGlobalSettingsSource().getLocation()
  187.             // }
  188.             // The following event type is available since Maven 3.3.1+
  189.             // else if (event instanceof DefaultToolchainsBuildingRequest) {
  190.             // DefaultToolchainsBuildingRequest r = null;
  191.             // r.getGlobalToolchainsSource().
  192.             // }
  193.             // The following event type is available since Maven 3.3.1+
  194.             // else if (event instanceof DefaultToolchainsBuildingResult) {
  195.             // DefaultToolchainsBuildingResult r = null;
  196.             // r.getEffectiveToolchains();
  197.             // r.getProblems();
  198.             // }
  199.             else
  200.             {
  201.                 // TODO: What kind of event we haven't considered?
  202.                 LOGGER.debug( "MBTP: Event {}", event.getClass().getCanonicalName() );
  203.             }
  204.         }
  205.         catch ( Exception e )
  206.         {
  207.             LOGGER.error( "MBTP: Exception", e );
  208.         }
  209.     }

  211.     @Override
  212.     public void close()
  213.     {
  214.         if ( !activated ) {
  215.             return;
  216.         }
  217.         LOGGER.debug( "MBTP: done." );
  218.     }

  220.     private void dependencyResolutionResult( DependencyResolutionResult event )
  221.     {
  222.         LOGGER.debug( "MBTP: dependencyResolutionResult() {}", event.getResolvedDependencies().size() );
  223.     }

  225.     private void dependencyResolutionRequest( DependencyResolutionRequest event )
  226.     {
  227.         LOGGER.debug( "MBTP: dependencyResolutionRequest()" );
  228.     }

  230.     private void repositoryEventHandler( org.eclipse.aether.RepositoryEvent repositoryEvent )
  231.     {
  232.         RepositoryEvent.EventType type = repositoryEvent.getType();
  233.         switch ( type )
  234.         {
  235.             case ARTIFACT_DOWNLOADING:
  236.                 LOGGER.debug( "MBTP: repositoryEventHandler {}", type );
  237.                 downloadTimer.start( repositoryEvent );
  238.                 break;
  239.             case ARTIFACT_DOWNLOADED:
  240.                 LOGGER.debug( "MBTP: repositoryEventHandler {}", type );
  241.                 downloadTimer.stop( repositoryEvent );
  242.                 break;

  244.             case ARTIFACT_DEPLOYING:
  245.                 deployTimer.start( repositoryEvent );
  246.                 break;
  247.             case ARTIFACT_DEPLOYED:
  248.                 deployTimer.stop( repositoryEvent );
  249.                 break;

  251.             case ARTIFACT_INSTALLING:
  252.                 installTimer.start( repositoryEvent );
  253.                 break;
  254.             case ARTIFACT_INSTALLED:
  255.                 installTimer.stop( repositoryEvent );
  256.                 break;

  258.             case METADATA_DEPLOYING:
  259.                 metadataDeploymentTimer.start( repositoryEvent );
  260.                 break;
  261.             case METADATA_DEPLOYED:
  262.                 metadataDeploymentTimer.stop( repositoryEvent );
  263.                 break;

  265.             case METADATA_DOWNLOADING:
  266.                 LOGGER.debug( "MBTP: repositoryEventHandler {}", type );
  267.                 metadataDownloadTimer.start( repositoryEvent );
  268.                 break;
  269.             case METADATA_DOWNLOADED:
  270.                 LOGGER.debug( "MBTP: repositoryEventHandler {}", type );
  271.                 metadataDownloadTimer.stop( repositoryEvent );
  272.                 break;

  274.             case METADATA_INSTALLING:
  275.                 LOGGER.debug( "MBTP: repositoryEventHandler {}", type );
  276.                 metadataInstallTimer.start( repositoryEvent );
  277.                 break;
  278.             case METADATA_INSTALLED:
  279.                 LOGGER.debug( "MBTP: repositoryEventHandler {}", type );
  280.                 metadataInstallTimer.stop( repositoryEvent );
  281.                 break;

  283.             case ARTIFACT_RESOLVING:
  284.             case ARTIFACT_RESOLVED:
  285.             case ARTIFACT_DESCRIPTOR_INVALID:
  286.             case ARTIFACT_DESCRIPTOR_MISSING:
  287.             case METADATA_RESOLVED:
  288.             case METADATA_RESOLVING:
  289.             case METADATA_INVALID:
  290.                 // Those events are not recorded.
  291.                 break;

  293.             default:
  294.                 LOGGER.error( "MBTP: repositoryEventHandler {}", type );
  295.                 break;
  296.         }
  297.     }

  299.     private void executionEventHandler( ExecutionEvent executionEvent )
  300.     {
  301.         if ( !activated ) {
  302.             return;
  303.         }
  304.         LOGGER.debug( "executionEventHandler: {}", executionEvent.getType() );
  305.         ExecutionEvent.Type type = executionEvent.getType();
  306.         switch ( type )
  307.         {
  308.             case ProjectDiscoveryStarted:
  309.                 // Start reading the pom files..
  310.                 discoveryTimer.discoveryStart();
  311.                 break;
  312.             case SessionStarted:
  313.                 // Reading of pom files done and structure now there.
  314.                 discoveryTimer.discoveryStop();
  315.                 sessionTimer.sessionStart();
  316.                 break;
  317.             case SessionEnded:
  318.                 // Everything is done.
  319.                 LOGGER.info( "MBTP: Session Ended");
  320.                 sessionTimer.sessionStop();
  321.                 break;

  323.             case ForkStarted:
  324.                 forkTimer.start();
  325.                 break;
  326.             case ForkFailed:
  327.             case ForkSucceeded:
  328.                 forkTimer.stop();
  329.                 break;

  331.             case ForkedProjectStarted:
  332.                 forkProject.projectStart( executionEvent );
  333.                 break;
  334.             case ForkedProjectFailed:
  335.             case ForkedProjectSucceeded:
  336.                 forkProject.projectStop( executionEvent );
  337.                 break;

  339.             case MojoStarted:
  340.                 String phaseStart = executionEvent.getMojoExecution().getLifecyclePhase();
  341.                 // Key: phase, project, mojo
  342.                 if ( phaseStart == null )
  343.                 {
  344.                     goalTimer.mojoStart( executionEvent );
  345.                 }
  346.                 else
  347.                 {
  348.                     collectAllLifeCyclePhases( phaseStart );
  349.                     mojoTimer.mojoStart( executionEvent );
  350.                 }
  351.                 break;

  353.             case MojoFailed:
  354.             case MojoSucceeded:
  355.             case MojoSkipped:
  356.                 String phaseStop = executionEvent.getMojoExecution().getLifecyclePhase();
  357.                 if ( phaseStop == null )
  358.                 {
  359.                     goalTimer.mojoStop( executionEvent );
  360.                 }
  361.                 else
  362.                 {
  363.                     mojoTimer.mojoStop( executionEvent );
  364.                 }
  365.                 break;

  367.             case ProjectStarted:
  368.                 projectTimer.projectStart( executionEvent );
  369.                 break;

  371.             case ProjectFailed:
  372.             case ProjectSucceeded:
  373.             case ProjectSkipped:
  374.                 projectTimer.projectStop( executionEvent );
  375.                 break;

  377.             default:
  378.                 LOGGER.error( "MBTP: executionEventHandler: {}", type );
  379.                 break;
  380.         }

  382.     }

  384.     private void executionRequestEventHandler( MavenExecutionRequest event )
  385.     {
  386.         LOGGER.debug( "MBTP: executionRequestEventHandler: {}", event.getExecutionListener() );
  387.     }

  389.     private void executionResultEventHandler( MavenExecutionResult event )
  390.     {
  391.         LOGGER.debug( "MBTP: executionResultEventHandler: {}", event.getProject() );
  392.         LOGGER.info( "--             Maven Build Time Profiler Summary                      --" );
  393.         LOGGER.info(SEPARATION_LINE);

  395.         discoveryTimer.report();

  397.         if ( mojoTimer.hasEvents() )
  398.         {
  399.             LOGGER.info( "Project Build Time (reactor order):" );
  400.             LOGGER.info( "" );
  401.             for ( MavenProject mavenProject : event.getTopologicallySortedProjects() )
  402.             {
  403.                 LOGGER.info( "{}:", mavenProject.getName() );

  405.                 for ( String phase : lifeCyclePhases )
  406.                 {
  407.                     ProjectKey projectKey = mavenProjectToProjectKey( mavenProject );

  409.                     if ( !mojoTimer.hasTimeForProjectAndPhase( projectKey, phase ) )
  410.                     {
  411.                         continue;
  412.                     }

  414.                     long timeForPhaseAndProjectInMillis =
  415.                         mojoTimer.getTimeForProjectAndPhaseInMillis( projectKey, phase );
  416.                     String formattedTime = String.format("%8d", timeForPhaseAndProjectInMillis);
  417.                     LOGGER.info( "    {} ms : {}", formattedTime, phase );

  419.                 }

  421.             }
  422.             LOGGER.info(SEPARATION_LINE);
  423.             LOGGER.info( "Lifecycle Phase summary:" );
  424.             LOGGER.info( "" );
  425.             for ( String phase : lifeCyclePhases )
  426.             {
  427.                 long timeForPhaseInMillis = mojoTimer.getTimeForPhaseInMillis( phase );
  428.                 LOGGER.info( "{} ms : {}", String.format( "%8d", timeForPhaseInMillis ), phase );
  429.             }

  431.             // List all plugins per phase
  432.             LOGGER.info(SEPARATION_LINE);
  433.             LOGGER.info( "Plugins in lifecycle Phases:" );
  434.             LOGGER.info( "" );
  435.             for ( String phase : lifeCyclePhases )
  436.             {
  437.                 LOGGER.info( "{}:", phase );
  438.                 Map<ProjectMojo, SystemTime> plugisInPhase = mojoTimer.getPluginsInPhase( phase );
  439.                 for ( Entry<ProjectMojo, SystemTime> pluginInPhase : plugisInPhase.entrySet() )
  440.                 {
  441.                     LOGGER.info( "{} ms: {}", String.format( "%8d", pluginInPhase.getValue().getElapsedTime() ),
  442.                                  pluginInPhase.getKey().getMojo().getFullId() );
  443.                 }

  445.             }

  447.             LOGGER.info( "" );
  448.             long timeForPlugins = mojoTimer.getTimeForPlugins();
  449.             String formattedTime = String.format("%8d", timeForPlugins);
  450.             LOGGER.info("{} ms plugins execution summary.", formattedTime);
  451.             LOGGER.info(SEPARATION_LINE);
  452.         }

  454.         if ( goalTimer.hasEvents() )
  455.         {
  456.             LOGGER.info( "Plugins directly called via goals:" );
  457.             LOGGER.info( "" );
  458.             goalTimer.report();
  459.             LOGGER.info(SEPARATION_LINE);
  460.         }

  462.         installTimer.report();
  463.         downloadTimer.report();
  464.         deployTimer.report();
  465.         metadataInstallTimer.report();
  466.         metadataDownloadTimer.report();
  467.         metadataDeploymentTimer.report();

  469.         forkTimer.report();
  470.         forkProject.report();
  471.     }

  473.     private ProjectKey mavenProjectToProjectKey( MavenProject project )
  474.     {
  475.         return new ProjectKey( project.getGroupId(), project.getArtifactId(), project.getVersion() );
  476.     }

  478.     private void collectAllLifeCyclePhases(String phase )
  479.     {
  480.         // Phase can be null if you call maven via:
  481.         // mvn site:stage (no life cycle started.)
  482.         if ( phase == null )
  483.         {
  484.             return;
  485.         }
  486.         LOGGER.debug( "collectAllLifeCyclePhases({})", phase );
  487.         if ( !lifeCyclePhases.contains( phase ) )
  488.         {
  489.             lifeCyclePhases.add( phase );
  490.         }
  491.     }

  493. }
Created with JaCoCo 0.8.13.202504020838