diff options
Diffstat (limited to 'src/main/java/com/google/devtools/build/lib/profiler/output/PhaseText.java')
| -rw-r--r-- | src/main/java/com/google/devtools/build/lib/profiler/output/PhaseText.java | 219 |
1 files changed, 219 insertions, 0 deletions
diff --git a/src/main/java/com/google/devtools/build/lib/profiler/output/PhaseText.java b/src/main/java/com/google/devtools/build/lib/profiler/output/PhaseText.java new file mode 100644 index 0000000000..6157fbb5f6 --- /dev/null +++ b/src/main/java/com/google/devtools/build/lib/profiler/output/PhaseText.java @@ -0,0 +1,219 @@ +// Copyright 2015 Google Inc. All rights reserved. +// +// Licensed under the Apache License, Version 2.0 (the "License"); +// you may not use this file except in compliance with the License. +// You may obtain a copy of the License at +// +// http://www.apache.org/licenses/LICENSE-2.0 +// +// Unless required by applicable law or agreed to in writing, software +// distributed under the License is distributed on an "AS IS" BASIS, +// WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. +// See the License for the specific language governing permissions and +// limitations under the License. +package com.google.devtools.build.lib.profiler.output; + +import com.google.devtools.build.lib.profiler.ProfilePhase; +import com.google.devtools.build.lib.profiler.ProfilerTask; +import com.google.devtools.build.lib.profiler.statistics.CriticalPathStatistics; +import com.google.devtools.build.lib.profiler.statistics.PhaseStatistics; +import com.google.devtools.build.lib.profiler.statistics.PhaseSummaryStatistics; +import com.google.devtools.build.lib.profiler.statistics.PhaseVfsStatistics; +import com.google.devtools.build.lib.profiler.statistics.PhaseVfsStatistics.Stat; +import com.google.devtools.build.lib.util.TimeUtilities; + +import java.io.PrintStream; +import java.util.Arrays; +import java.util.EnumMap; +import java.util.Map.Entry; + +/** + * Output {@link PhaseSummaryStatistics}, {@link PhaseStatistics} and {@link PhaseVfsStatistics} + * in text format. + */ +public final class PhaseText extends TextPrinter { + + private final PhaseSummaryStatistics phaseSummaryStats; + private final EnumMap<ProfilePhase, PhaseStatistics> phaseStatistics; + private final CriticalPathStatistics criticalPathStatistics; + private final int vfsStatsLimit; + private final int missingActionsCount; + + /** + * @param vfsStatsLimit maximum number of VFS statistics to print, or -1 for no limit. + */ + public PhaseText( + PrintStream out, + PhaseSummaryStatistics phaseSummaryStats, + EnumMap<ProfilePhase, PhaseStatistics> phaseStatistics, + CriticalPathStatistics critPathStats, + int missingActionsCount, + int vfsStatsLimit) { + super(out); + this.phaseSummaryStats = phaseSummaryStats; + this.phaseStatistics = phaseStatistics; + this.criticalPathStatistics = critPathStats; + this.missingActionsCount = missingActionsCount; + this.vfsStatsLimit = vfsStatsLimit; + } + + public void print() { + printPhaseSummaryStatistics(); + + for (ProfilePhase phase : + Arrays.asList(ProfilePhase.INIT, ProfilePhase.LOAD, ProfilePhase.ANALYZE)) { + PhaseStatistics statistics = phaseStatistics.get(phase); + if (statistics.wasExecuted()) { + printPhaseStatistics(statistics); + } + } + printExecutionPhaseStatistics(); + } + + /** + * 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(); + } + + /** + * 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(); + if (vfsStatsLimit != 0) { + printVfsStatistics(stats.getVfsStatistics()); + printLn(); + } + } + } + + 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 = new CriticalPathText(out, criticalPathStatistics, execTime); + criticalPaths.printTimingBreakdown(); + printLn(); + + printTimingDistribution(execPhase); + printLn(); + + 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(); + } + + if (vfsStatsLimit != 0) { + printVfsStatistics(execPhase.getVfsStatistics()); + printLn(); + } + } + + /** + * 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))); + } + } + + /** + * 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(PhaseVfsStatistics stats) { + lnPrint("VFS path statistics:"); + lnPrintf("%15s %10s %10s %s", "Type", "Frequency", "Duration", "Path"); + + for (ProfilerTask type : stats) { + int numPrinted = 0; + for (Entry<Stat, String> 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.getKey().count, + TimeUtilities.prettyTime(stat.getKey().duration), + stat.getValue()); + } + } + } +} + + |