Skip to content

Commit

Permalink
Include project name in lifecycle phase summary
Browse files Browse the repository at this point in the history 
For multi-module projects there is currently no indication of which project caused a particular mojo execution. This is an alternate solution to khmarbaise#4.

Current output:
```
[INFO] generate-sources:
[INFO]        1 ms: org.codehaus.mojo:build-helper-maven-plugin:3.3.0:add-source:add-antlr-sources
[INFO]        0 ms: org.codehaus.mojo:build-helper-maven-plugin:3.3.0:add-source:add-antlr-sources
[INFO]     3247 ms: com.twitter:scrooge-maven-plugin:20.1.0:compile:thrift-sources
[INFO]        1 ms: org.codehaus.mojo:build-helper-maven-plugin:3.3.0:add-source:add-antlr-sources
[INFO]     1703 ms: com.twitter:scrooge-maven-plugin:20.1.0:compile:thrift-sources
[INFO]        1 ms: org.codehaus.mojo:build-helper-maven-plugin:3.3.0:add-source:add-antlr-sources
[INFO]        0 ms: org.codehaus.mojo:build-helper-maven-plugin:3.3.0:add-source:add-antlr-sources
[INFO]        0 ms: org.codehaus.mojo:build-helper-maven-plugin:3.3.0:add-source:add-antlr-sources
[INFO]        0 ms: org.codehaus.mojo:build-helper-maven-plugin:3.3.0:add-source:add-antlr-sources
[INFO]        0 ms: org.codehaus.mojo:build-helper-maven-plugin:3.3.0:add-source:add-antlr-sources
[INFO]        0 ms: org.codehaus.mojo:build-helper-maven-plugin:3.3.0:add-source:add-antlr-sources
[INFO]        0 ms: org.codehaus.mojo:build-helper-maven-plugin:3.3.0:add-source:add-antlr-sources
[INFO]        1 ms: org.codehaus.mojo:build-helper-maven-plugin:3.3.0:add-source:add-antlr-sources
[INFO]        1 ms: org.codehaus.mojo:build-helper-maven-plugin:3.3.0:add-source:add-antlr-sources
[INFO]        0 ms: org.codehaus.mojo:build-helper-maven-plugin:3.3.0:add-source:add-antlr-sources
[INFO]        1 ms: org.codehaus.mojo:build-helper-maven-plugin:3.3.0:add-source:add-antlr-sources
[INFO]      132 ms: com.twitter:scrooge-maven-plugin:20.1.0:compile:thrift-sources
[INFO]        1 ms: org.codehaus.mojo:build-helper-maven-plugin:3.3.0:add-source:add-antlr-sources
[INFO]        0 ms: org.codehaus.mojo:build-helper-maven-plugin:3.3.0:add-source:add-antlr-sources
[INFO]        2 ms: org.codehaus.mojo:build-helper-maven-plugin:3.3.0:add-source:add-antlr-sources
[INFO]        0 ms: org.codehaus.mojo:build-helper-maven-plugin:3.3.0:add-source:add-antlr-sources
[INFO]        0 ms: org.codehaus.mojo:build-helper-maven-plugin:3.3.0:add-source:add-antlr-sources
[INFO]      303 ms: com.twitter:scrooge-maven-plugin:20.1.0:compile:thrift-sources
[INFO]      531 ms: org.antlr:antlr4-maven-plugin:4.9.3:antlr4:antlr
[INFO]        1 ms: org.codehaus.mojo:build-helper-maven-plugin:3.3.0:add-source:add-antlr-sources
[INFO]        1 ms: org.codehaus.mojo:build-helper-maven-plugin:3.3.0:add-source:add-antlr-sources
[INFO]        1 ms: org.codehaus.mojo:build-helper-maven-plugin:3.3.0:add-source:add-antlr-sources
[INFO]     1423 ms: org.antlr:antlr4-maven-plugin:4.9.3:antlr4:antlr
[INFO]        0 ms: org.codehaus.mojo:build-helper-maven-plugin:3.3.0:add-source:add-antlr-sources
[INFO]      117 ms: org.codehaus.mojo:build-helper-maven-plugin:3.3.0:add-source:add-antlr-sources
[INFO]     1987 ms: org.antlr:antlr4-maven-plugin:4.9.3:antlr4:antlr
[INFO]        1 ms: org.codehaus.mojo:build-helper-maven-plugin:3.3.0:add-source:add-antlr-sources
[INFO]        0 ms: org.codehaus.mojo:build-helper-maven-plugin:3.3.0:add-source:add-antlr-sources
[INFO]        1 ms: org.codehaus.mojo:build-helper-maven-plugin:3.3.0:add-source:add-antlr-sources
[INFO]        1 ms: org.codehaus.mojo:build-helper-maven-plugin:3.3.0:add-source:add-antlr-sources
[INFO]        1 ms: org.codehaus.mojo:build-helper-maven-plugin:3.3.0:add-source:add-antlr-sources
[INFO]        1 ms: org.codehaus.mojo:build-helper-maven-plugin:3.3.0:add-source:add-antlr-sources
[INFO]        0 ms: org.codehaus.mojo:build-helper-maven-plugin:3.3.0:add-source:add-antlr-sources
```

New output:
```
[INFO] Plugins in lifecycle Phases:
[INFO]
[INFO] clean:
[INFO]      126 ms : Maven :: Build Time Profiler@org.apache.maven.plugins:maven-clean-plugin:3.1.0:clean (default-clean)
[INFO] validate:
[INFO]      145 ms : Maven :: Build Time Profiler@org.apache.maven.plugins:maven-enforcer-plugin:3.0.0:enforce (enforce-maven)
[INFO] initialize:
[INFO]       85 ms : Maven :: Build Time Profiler@org.jacoco:jacoco-maven-plugin:0.8.8:prepare-agent (default)
[INFO] generate-sources:
[INFO]      137 ms : Maven :: Build Time Profiler@org.codehaus.mojo:templating-maven-plugin:1.0.0:filter-sources (default)
[INFO] process-resources:
[INFO]       74 ms : Maven :: Build Time Profiler@org.apache.maven.plugins:maven-resources-plugin:3.2.0:resources (default-resources)
[INFO] compile:
[INFO]      837 ms : Maven :: Build Time Profiler@org.apache.maven.plugins:maven-compiler-plugin:3.10.0:compile (default-compile)
[INFO] process-classes:
[INFO]       54 ms : Maven :: Build Time Profiler@org.sonatype.plugins:sisu-maven-plugin:1.1:main-index (generate-index)
[INFO] process-test-resources:
[INFO]        2 ms : Maven :: Build Time Profiler@org.apache.maven.plugins:maven-resources-plugin:3.2.0:testResources (default-testResources)
[INFO] test-compile:
[INFO]      278 ms : Maven :: Build Time Profiler@org.apache.maven.plugins:maven-compiler-plugin:3.10.0:testCompile (default-testCompile)
[INFO] test:
[INFO]     3117 ms : Maven :: Build Time Profiler@org.apache.maven.plugins:maven-surefire-plugin:3.0.0-M6:test (default-test)
[INFO] package:
[INFO]      504 ms : Maven :: Build Time Profiler@org.apache.maven.plugins:maven-site-plugin:3.11.0:attach-descriptor (attach-descriptor)
[INFO]       89 ms : Maven :: Build Time Profiler@org.apache.maven.plugins:maven-shade-plugin:3.3.0:shade (default)
[INFO]      267 ms : Maven :: Build Time Profiler@org.apache.maven.plugins:maven-jar-plugin:3.2.2:jar (default-jar)
[INFO] verify:
[INFO]      228 ms : Maven :: Build Time Profiler@org.jacoco:jacoco-maven-plugin:0.8.8:report (default)
[INFO] install:
[INFO]       67 ms : Maven :: Build Time Profiler@org.apache.maven.plugins:maven-install-plugin:3.0.0-M1:install (default-install)
```
  • Loading branch information
@clayreimann
clayreimann committed May 19, 2022
1 parent 02be61c commit 9b5f98c
Show file tree
Hide file tree
Showing 7 changed files with 110 additions and 80 deletions.
2 changes: 1 addition & 1 deletion .drone.yml
View file
Original file line number Diff line number Diff line change
Expand Up @@ -30,7 +30,7 @@ steps:
mount:
- .repo

- name: mavenjdk8
- name: mavenjdk11
pull: always
image: docker.io/maven:3.8.4-openjdk-11-slim
volumes:
Expand Down
114 changes: 66 additions & 48 deletions src/main/java/com/soebes/maven/extensions/BuildTimeProfiler.java
View file
Original file line number Diff line number Diff line change
Expand Up @@ -24,6 +24,8 @@
import java.util.List;
import java.util.Map;
import java.util.Map.Entry;
import java.util.function.BiConsumer;
import java.util.stream.Collectors;

import javax.inject.Named;
import javax.inject.Singleton;
Expand All @@ -47,6 +49,8 @@
import com.soebes.maven.extensions.metadata.MetadataDownloadTimer;
import com.soebes.maven.extensions.metadata.MetadataInstallTimer;

import static com.soebes.maven.extensions.ProjectKey.fromMavenProject;

/**
* @author Karl Heinz Marbaise <a href="mailto:kama@soebes.de">kama@soebes.de</a>
*/
Expand All @@ -57,6 +61,8 @@ public class BuildTimeProfiler
{
private static final Logger LOGGER = LoggerFactory.getLogger(BuildTimeProfiler.class);

private static final String DIVIDER = "------------------------------------------------------------------------";

final List<String> lifeCyclePhases;

private final DiscoveryTimer discoveryTimer;
Expand Down Expand Up @@ -397,67 +403,29 @@ private void executionResultEventHandler( MavenExecutionResult event )
LOGGER.debug( "MBTP: executionResultEventHandler: {}", event.getProject() );

LOGGER.info( "-- Maven Build Time Profiler Summary --" );
LOGGER.info( "------------------------------------------------------------------------" );
LOGGER.info(DIVIDER);

discoveryTimer.report();

if ( mojoTimer.hasEvents() )
{
LOGGER.info( "Project Build Time (reactor order):" );
LOGGER.info( "" );
for ( MavenProject mavenProject : event.getTopologicallySortedProjects() )
{
LOGGER.info( "{}:", mavenProject.getName() );

for ( String phase : lifeCyclePhases )
{
ProjectKey projectKey = mavenProjectToProjectKey( mavenProject );

if ( !mojoTimer.hasTimeForProjectAndPhase( projectKey, phase ) )
{
continue;
}
logProjects(event);
LOGGER.info(DIVIDER);

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

}

}
LOGGER.info( "------------------------------------------------------------------------" );
LOGGER.info( "Lifecycle Phase summary:" );
LOGGER.info( "" );
for ( String phase : lifeCyclePhases )
{
long timeForPhaseInMillis = mojoTimer.getTimeForPhaseInMillis( phase );
LOGGER.info( "{} ms : {}", String.format( "%8d", timeForPhaseInMillis ), phase );
}
logPhaseSummary();
LOGGER.info(DIVIDER);

// List all plugins per phase
LOGGER.info( "------------------------------------------------------------------------" );
LOGGER.info( "Plugins in lifecycle Phases:" );
LOGGER.info( "" );
for ( String phase : lifeCyclePhases )
{
LOGGER.info( "{}:", phase );
Map<ProjectMojo, SystemTime> plugisInPhase = mojoTimer.getPluginsInPhase( phase );
for ( Entry<ProjectMojo, SystemTime> pluginInPhase : plugisInPhase.entrySet() )
{
LOGGER.info( "{} ms: {}", String.format( "%8d", pluginInPhase.getValue().getElapsedTime() ),
pluginInPhase.getKey().getMojo().getFullId() );
}

}
LOGGER.info( "------------------------------------------------------------------------" );
logDetailedPhaseExecutions();
LOGGER.info(DIVIDER);
}

if ( goalTimer.hasEvents() )
{
LOGGER.info( "Plugins directly called via goals:" );
LOGGER.info( "" );
goalTimer.report();
LOGGER.info( "------------------------------------------------------------------------" );
LOGGER.info(DIVIDER);
}

installTimer.report();
Expand All @@ -471,9 +439,59 @@ private void executionResultEventHandler( MavenExecutionResult event )
forkProject.report();
}

private ProjectKey mavenProjectToProjectKey( MavenProject project )

private void logProjects(MavenExecutionResult event)
{
LOGGER.info( "Project Build Time (reactor order):" );
LOGGER.info( "" );
for ( MavenProject mavenProject : event.getTopologicallySortedProjects() )
{
LOGGER.info( "{}:", mavenProject.getName() );

for ( String phase : lifeCyclePhases )
{
ProjectKey projectKey = fromMavenProject( mavenProject );

if ( !mojoTimer.hasTimeForProjectAndPhase( projectKey, phase ) )
{
continue;
}

logTime( mojoTimer.getTimeForProjectAndPhaseInMillis( projectKey, phase ), phase );
}

}
}

private void logPhaseSummary()
{
LOGGER.info( "Lifecycle Phase summary:" );
LOGGER.info( "" );
for ( String phase : lifeCyclePhases )
{
logTime( mojoTimer.getTimeForPhaseInMillis( phase ), phase );
}
}

private void logDetailedPhaseExecutions()
{
LOGGER.info( "Plugins in lifecycle Phases:" );
LOGGER.info( "" );
for ( String phase : lifeCyclePhases )
{
LOGGER.info( "{}:", phase );
Map<ProjectMojo, SystemTime> plugisInPhase = mojoTimer.getPluginsInPhase( phase );
for ( Entry<ProjectMojo, SystemTime> pluginInPhase : plugisInPhase.entrySet() )
{
logTime( pluginInPhase.getValue().getElapsedTime(), pluginInPhase.getKey().getLifecycleId() );
}

}
}

private void logTime(long millis, String label)
{
return new ProjectKey( project.getGroupId(), project.getArtifactId(), project.getVersion() );
LOGGER.info( "{} ms : {}", String.format( "%8d", millis ), label );
}

private void collectAllLifeCylcePhases( String phase )
Expand Down
12 changes: 4 additions & 8 deletions src/main/java/com/soebes/maven/extensions/GoalTimer.java
View file
Original file line number Diff line number Diff line change
Expand Up @@ -6,10 +6,11 @@

import org.apache.maven.execution.ExecutionEvent;
import org.apache.maven.plugin.MojoExecution;
import org.apache.maven.project.MavenProject;
import org.slf4j.Logger;
import org.slf4j.LoggerFactory;

import static com.soebes.maven.extensions.ProjectKey.fromMavenProject;

/**
* @author Karl Heinz Marbaise <a href="mailto:kama@soebes.de">kama@soebes.de</a>
*/
Expand All @@ -29,11 +30,6 @@ public boolean hasEvents()
return !timerEvents.isEmpty();
}

private ProjectKey createProjectKey( MavenProject project )
{
return new ProjectKey( project.getGroupId(), project.getArtifactId(), project.getVersion() );
}

private GoalKey createGoalKey( MojoExecution mojo )
{
return new GoalKey( mojo.getGroupId(), mojo.getArtifactId(), mojo.getVersion(), mojo.getGoal(),
Expand All @@ -43,14 +39,14 @@ private GoalKey createGoalKey( MojoExecution mojo )
public void mojoStart( ExecutionEvent event )
{
ProjectGoal pm =
new ProjectGoal( createProjectKey( event.getProject() ), createGoalKey( event.getMojoExecution() ) );
new ProjectGoal( fromMavenProject(event.getProject()), createGoalKey(event.getMojoExecution() ) );
timerEvents.put( pm, new SystemTime().start() );
}

public void mojoStop( ExecutionEvent event )
{
ProjectGoal pm =
new ProjectGoal( createProjectKey( event.getProject() ), createGoalKey( event.getMojoExecution() ) );
new ProjectGoal( fromMavenProject(event.getProject()), createGoalKey(event.getMojoExecution() ) );
if ( !timerEvents.containsKey( pm ) )
{
throw new IllegalArgumentException( "Unknown mojoId (" + pm.getId() + ")" );
Expand Down
12 changes: 12 additions & 0 deletions src/main/java/com/soebes/maven/extensions/MojoKey.java
View file
Original file line number Diff line number Diff line change
Expand Up @@ -19,6 +19,8 @@
* under the License.
*/

import org.apache.maven.plugin.MojoExecution;

/**
* @author Karl Heinz Marbaise <a href="mailto:kama@soebes.de">kama@soebes.de</a>
*/
Expand All @@ -31,6 +33,11 @@ class MojoKey

private String phase;

public static MojoKey fromMojo(MojoExecution mojo) {
return new MojoKey( mojo.getGroupId(), mojo.getArtifactId(), mojo.getVersion(), mojo.getGoal(),
mojo.getExecutionId(), mojo.getLifecyclePhase() );
}

public MojoKey( String groupId, String artifactId, String version, String goal, String executionId,
String lifeCyclePhase )
{
Expand Down Expand Up @@ -75,6 +82,11 @@ public String getFullId()
return super.getId() + ":" + getGoal() + " (" + getExecutionId() + ")";
}

public String getFullIdWithPhase()
{
return super.getId() + ":" + getGoal() + " (" + getExecutionId() + ":" + getPhase() + ")";
}

@Override
public int hashCode()
{
Expand Down
21 changes: 5 additions & 16 deletions src/main/java/com/soebes/maven/extensions/MojoTimer.java
View file
Original file line number Diff line number Diff line change
Expand Up @@ -30,6 +30,8 @@
import org.slf4j.Logger;
import org.slf4j.LoggerFactory;

import static com.soebes.maven.extensions.MojoKey.fromMojo;

/**
* @author Karl Heinz Marbaise <a href="mailto:kama@soebes.de">kama@soebes.de</a>
*/
Expand All @@ -44,17 +46,6 @@ public MojoTimer()
this.timerEvents = new ConcurrentHashMap<>();
}

private ProjectKey createProjectKey( MavenProject project )
{
return new ProjectKey( project.getGroupId(), project.getArtifactId(), project.getVersion() );
}

private MojoKey createMojoKey( MojoExecution mojo )
{
return new MojoKey( mojo.getGroupId(), mojo.getArtifactId(), mojo.getVersion(), mojo.getGoal(),
mojo.getExecutionId(), mojo.getLifecyclePhase() );
}

public boolean hasEvents()
{
return !this.timerEvents.isEmpty();
Expand All @@ -63,15 +54,13 @@ public boolean hasEvents()
public void mojoStart( ExecutionEvent event )
{

ProjectMojo pm =
new ProjectMojo( createProjectKey( event.getProject() ), createMojoKey( event.getMojoExecution() ) );
ProjectMojo pm = new ProjectMojo( event.getProject(), fromMojo( event.getMojoExecution() ) );
timerEvents.put( pm, new SystemTime().start() );
}

public void mojoStop( ExecutionEvent event )
{
ProjectMojo pm =
new ProjectMojo( createProjectKey( event.getProject() ), createMojoKey( event.getMojoExecution() ) );
ProjectMojo pm = new ProjectMojo( event.getProject(), fromMojo( event.getMojoExecution() ) );
if ( !timerEvents.containsKey( pm ) )
{
throw new IllegalArgumentException( "Unknown mojoId (" + pm + ")" );
Expand Down Expand Up @@ -139,7 +128,7 @@ public void report()
{
for ( Entry<ProjectMojo, SystemTime> item : this.timerEvents.entrySet() )
{
LOGGER.info( "{} : {}", item.getKey().getId(), item.getValue().getElapsedTime() );
LOGGER.info( "{} : {}", item.getKey().getFullId(), item.getValue().getElapsedTime() );
}
}
}
6 changes: 6 additions & 0 deletions src/main/java/com/soebes/maven/extensions/ProjectKey.java
View file
Original file line number Diff line number Diff line change
Expand Up @@ -19,6 +19,8 @@
* under the License.
*/

import org.apache.maven.project.MavenProject;

/**
* @author Karl Heinz Marbaise <a href="mailto:kama@soebes.de">kama@soebes.de</a>
*/
Expand All @@ -30,6 +32,10 @@ class ProjectKey

private final String version;

public static ProjectKey fromMavenProject(MavenProject project) {
return new ProjectKey(project.getGroupId(), project.getArtifactId(), project.getVersion());
}

public ProjectKey( final String groupId, final String artifactId, final String version )
{
super();
Expand Down
23 changes: 16 additions & 7 deletions src/main/java/com/soebes/maven/extensions/ProjectMojo.java
View file
Original file line number Diff line number Diff line change
Expand Up @@ -19,19 +19,26 @@
* under the License.
*/

import org.apache.maven.project.MavenProject;

import static com.soebes.maven.extensions.ProjectKey.fromMavenProject;

/**
* @author Karl Heinz Marbaise <a href="mailto:kama@soebes.de">kama@soebes.de</a>
*/
class ProjectMojo
{
private ProjectKey project;

private String projectName;

private MojoKey mojo;

public ProjectMojo( ProjectKey project, MojoKey mojo )
public ProjectMojo( MavenProject project, MojoKey mojo )
{
super();
this.project = project;
this.project = fromMavenProject( project );
this.projectName = project.getName();
this.mojo = mojo;
}

Expand Down Expand Up @@ -65,12 +72,14 @@ public int hashCode()
return result;
}

public String getId()
public String getLifecycleId()
{
return projectName + "@" + mojo.getFullId();
}

public String getFullId()
{
String s1 = getMojo().getGroupId() + ":" + getMojo().getArtifactId() + ":" + getMojo().getVersion() + ":"
+ getMojo().getGoal() + " (" + getMojo().getExecutionId() + ":" + getMojo().getPhase() + ")";
String s2 = getProject().getGroupId() + ":" + getProject().getArtifactId() + ":" + getProject().getVersion();
return s1 + " @ " + s2;
return mojo.getFullIdWithPhase() + " @ " + project.getId();
}

@Override
Expand Down

0 comments on commit 9b5f98c

Please sign in to comment.