private void printExecutionPhaseStatistics() {
PhaseStatistics prepPhase = phaseStatistics.get(ProfilePhase.PREPARE);
PhaseStatistics execPhase = phaseStatistics.get(ProfilePhase.EXECUTE);
PhaseStatistics finishPhase = phaseStatistics.get(ProfilePhase.FINISH);
if (!execPhase.wasExecuted()) {
return;
}
lnPrint("=== EXECUTION PHASE INFORMATION ===\n");
long graphTime = execPhase.getTotalDurationNanos(ProfilerTask.ACTION_GRAPH);
long execTime = execPhase.getPhaseDurationNanos() - graphTime;
if (prepPhase.wasExecuted()) {
lnPrintf(
TWO_COLUMN_FORMAT,
"Total preparation time",
TimeUtilities.prettyTime(prepPhase.getPhaseDurationNanos()));
}
lnPrintf(
TWO_COLUMN_FORMAT,
"Total execution phase time",
TimeUtilities.prettyTime(execPhase.getPhaseDurationNanos()));
if (finishPhase.wasExecuted()) {
lnPrintf(
TWO_COLUMN_FORMAT,
"Total time finalizing build",
TimeUtilities.prettyTime(finishPhase.getPhaseDurationNanos()));
}
printLn();
lnPrintf(
TWO_COLUMN_FORMAT, "Action dependency map creation", TimeUtilities.prettyTime(graphTime));
lnPrintf(TWO_COLUMN_FORMAT, "Actual execution time", TimeUtilities.prettyTime(execTime));
CriticalPathText criticalPaths = null;
if (criticalPathStatistics.isPresent()) {
criticalPaths = new CriticalPathText(out, criticalPathStatistics.get(), execTime);
criticalPaths.printTimingBreakdown();
printLn();
}
printTimingDistribution(execPhase);
printLn();
if (criticalPathStatistics.isPresent()) {
criticalPaths.printCriticalPaths();
printLn();
}
if (missingActionsCount > 0) {
lnPrint(missingActionsCount);
print(
" action(s) are present in the"
+ " action graph but missing instrumentation data. Most likely the profile file"
+ " has been created during a failed or aborted build.");
printLn();
}
printVfsStatistics(execPhase.getVfsStatistics());
}
private void printCriticalPath(String title, CriticalPathEntry path) {
lnPrintf("%s (%s):", title, TimeUtilities.prettyTime(path.cumulativeDuration));
boolean isComponent = path.isComponent();
if (isComponent) {
lnPrintf("%6s %11s %8s %s", "Id", "Time", "Percentage", "Description");
} else {
lnPrintf("%6s %11s %8s %8s %s", "Id", "Time", "Share", "Critical", "Description");
}
long totalPathTime = path.cumulativeDuration;
for (CriticalPathEntry pathEntry : criticalPathStats.getMiddlemanFilteredPath(path)) {
String desc = pathEntry.task.getDescription().replace(':', ' ');
if (isComponent) {
lnPrintf(
"%6d %11s %8s %s",
pathEntry.task.id,
TimeUtilities.prettyTime(pathEntry.duration),
prettyPercentage((double) pathEntry.duration / totalPathTime),
desc);
} else {
lnPrintf(
"%6d %11s %8s %8s %s",
pathEntry.task.id,
TimeUtilities.prettyTime(pathEntry.duration),
prettyPercentage((double) pathEntry.duration / totalPathTime),
prettyPercentage((double) pathEntry.getCriticalTime() / totalPathTime),
desc);
}
}
MiddleManStatistics middleMan = MiddleManStatistics.create(path);
if (middleMan.count > 0) {
if (isComponent) {
lnPrintf(
" %11s %8s [%d middleman actions]",
TimeUtilities.prettyTime(middleMan.duration),
prettyPercentage((double) middleMan.duration / totalPathTime),
middleMan.count);
} else {
lnPrintf(
" %11s %8s %8s [%d middleman actions]",
TimeUtilities.prettyTime(middleMan.duration),
prettyPercentage((double) middleMan.duration / totalPathTime),
prettyPercentage((double) middleMan.criticalTime / totalPathTime),
middleMan.count);
}
}
}
/**
* Print a table for the phase overview with runtime and runtime percentage per phase and total.
*/
private void printPhaseSummaryStatistics() {
print("\n=== PHASE SUMMARY INFORMATION ===\n");
for (ProfilePhase phase : phaseSummaryStats) {
long phaseDuration = phaseSummaryStats.getDurationNanos(phase);
double relativeDuration = phaseSummaryStats.getRelativeDuration(phase);
lnPrintf(
THREE_COLUMN_FORMAT,
"Total " + phase.nick + " phase time",
TimeUtilities.prettyTime(phaseDuration),
prettyPercentage(relativeDuration));
}
lnPrintf(
THREE_COLUMN_FORMAT,
"Total run time",
TimeUtilities.prettyTime(phaseSummaryStats.getTotalDuration()),
"100.00%");
printLn();
}
void printCriticalPathTimingBreakdown(
CriticalPathEntry totalPath, CriticalPathEntry optimalPath) {
lnPrint(totalPath.task.type);
lnPrintf(
TWO_COLUMN_FORMAT,
"Worker thread scheduling delays",
TimeUtilities.prettyTime(criticalPathStats.getWorkerWaitTime()));
lnPrintf(
TWO_COLUMN_FORMAT,
"Main thread scheduling delays",
TimeUtilities.prettyTime(criticalPathStats.getMainThreadWaitTime()));
printLn();
lnPrint("Critical path time:");
long totalTime = totalPath.cumulativeDuration;
lnPrintf(
"%-37s %10s (%s of execution time)",
"Actual time",
TimeUtilities.prettyTime(totalTime),
prettyPercentage((double) totalTime / executionTime));
long optimalTime = optimalPath.cumulativeDuration;
lnPrintf(
"%-37s %10s (%s of execution time)",
"Time excluding scheduling delays",
TimeUtilities.prettyTime(optimalTime),
prettyPercentage((double) optimalTime / executionTime));
printLn();
// Artificial critical path if we ignore all the time spent in all tasks,
// except time directly attributed to the ACTION tasks.
lnPrint("Time related to:");
for (Pair<String, Double> relativePathDuration : criticalPathStats) {
lnPrintf(
TWO_COLUMN_FORMAT,
relativePathDuration.first,
prettyPercentage(relativePathDuration.second));
}
}
/**
* Prints a table of task types and their relative total and average execution time as well as how
* many tasks of each type there were
*/
private void printTimingDistribution(PhaseStatistics stats) {
lnPrint("Total time (across all threads) spent on:");
lnPrintf("%18s %8s %8s %11s", "Type", "Total", "Count", "Average");
for (ProfilerTask type : stats) {
lnPrintf(
"%18s %8s %8d %11s",
type.toString(),
prettyPercentage(stats.getTotalRelativeDuration(type)),
stats.getCount(type),
TimeUtilities.prettyTime(stats.getMeanDuration(type)));
}
}
/** Prints all statistics from {@link PhaseStatistics} in text form. */
private void printPhaseStatistics(PhaseStatistics stats) {
lnPrintf("=== %s PHASE INFORMATION ===\n", stats.getProfilePhase().nick.toUpperCase());
lnPrintf(
TWO_COLUMN_FORMAT,
"Total " + stats.getProfilePhase().nick + " phase time",
TimeUtilities.prettyTime(stats.getPhaseDurationNanos()));
printLn();
if (!stats.isEmpty()) {
printTimingDistribution(stats);
printLn();
printVfsStatistics(stats.getVfsStatistics());
}
}
/**
* Print the time spent on VFS operations on each path. Output is grouped by operation and sorted
* by descending duration. If multiple of the same VFS operation were logged for the same path,
* print the total duration.
*/
private void printVfsStatistics(@Nullable PhaseVfsStatistics stats) {
if (vfsStatsLimit == 0 || stats == null || stats.isEmpty()) {
return;
}
lnPrint("VFS path statistics:");
lnPrintf("%15s %10s %10s %s", "Type", "Frequency", "Duration", "Path");
for (ProfilerTask type : stats) {
int numPrinted = 0;
for (Stat stat : stats.getSortedStatistics(type)) {
if (vfsStatsLimit != -1 && numPrinted++ == vfsStatsLimit) {
lnPrintf("... %d more ...", stats.getStatisticsCount(type) - vfsStatsLimit);
break;
}
lnPrintf(
"%15s %10d %10s %s",
type.name(), stat.getCount(), TimeUtilities.prettyTime(stat.getDuration()), stat.path);
}
}
printLn();
}
private void printCriticalPath(String title, CriticalPathEntry path) {
lnPrintf("%s (%s):", title, TimeUtilities.prettyTime(path.cumulativeDuration));
boolean isComponent = path.isComponent();
if (isComponent) {
lnPrintf("%6s %11s %8s %s", "Id", "Time", "Percentage", "Description");
} else {
lnPrintf("%6s %11s %8s %8s %s", "Id", "Time", "Share", "Critical", "Description");
}
long totalPathTime = path.cumulativeDuration;
int middlemanCount = 0;
long middlemanDuration = 0L;
long middlemanCritTime = 0L;
for (; path != null; path = path.next) {
if (path.task.id < 0) {
// Ignore fake actions.
continue;
} else if (path.task.getDescription().startsWith(MiddlemanAction.MIDDLEMAN_MNEMONIC + " ")
|| path.task.getDescription().startsWith("TargetCompletionMiddleman")) {
// Aggregate middleman actions.
middlemanCount++;
middlemanDuration += path.duration;
middlemanCritTime += path.getCriticalTime();
} else {
String desc = path.task.getDescription().replace(':', ' ');
if (isComponent) {
lnPrintf(
"%6d %11s %8s %s",
path.task.id,
TimeUtilities.prettyTime(path.duration),
prettyPercentage((double) path.duration / totalPathTime),
desc);
} else {
lnPrintf(
"%6d %11s %8s %8s %s",
path.task.id,
TimeUtilities.prettyTime(path.duration),
prettyPercentage((double) path.duration / totalPathTime),
prettyPercentage((double) path.getCriticalTime() / totalPathTime),
desc);
}
}
}
if (middlemanCount > 0) {
if (isComponent) {
lnPrintf(
" %11s %8s [%d middleman actions]",
TimeUtilities.prettyTime(middlemanDuration),
prettyPercentage((double) middlemanDuration / totalPathTime),
middlemanCount);
} else {
lnPrintf(
" %11s %8s %8s [%d middleman actions]",
TimeUtilities.prettyTime(middlemanDuration),
prettyPercentage((double) middlemanDuration / totalPathTime),
prettyPercentage((double) middlemanCritTime / totalPathTime),
middlemanCount);
}
}
}