diff options
Diffstat (limited to 'src/main/java/com/google/devtools/build/lib/profiler/output')
7 files changed, 1241 insertions, 0 deletions
diff --git a/src/main/java/com/google/devtools/build/lib/profiler/output/CriticalPathText.java b/src/main/java/com/google/devtools/build/lib/profiler/output/CriticalPathText.java new file mode 100644 index 0000000000..b82778f5f9 --- /dev/null +++ b/src/main/java/com/google/devtools/build/lib/profiler/output/CriticalPathText.java @@ -0,0 +1,173 @@ +// 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.actions.MiddlemanAction; +import com.google.devtools.build.lib.profiler.ProfileInfo.CriticalPathEntry; +import com.google.devtools.build.lib.profiler.statistics.CriticalPathStatistics; +import com.google.devtools.build.lib.util.Pair; +import com.google.devtools.build.lib.util.TimeUtilities; + +import java.io.PrintStream; + +/** + * Generate textual output from {@link CriticalPathStatistics}. + */ +//TODO(bazel-team): Also print remote vs build stats recorded by Logging.CriticalPathStats +public final class CriticalPathText extends TextPrinter { + + private final CriticalPathStatistics criticalPathStats; + private long executionTime; + + public CriticalPathText( + PrintStream out, CriticalPathStatistics critPathStats, long executionTime) { + super(out); + this.criticalPathStats = critPathStats; + this.executionTime = executionTime; + } + + public void printTimingBreakdown() { + CriticalPathEntry totalPath = criticalPathStats.getTotalPath(); + CriticalPathEntry optimalPath = criticalPathStats.getOptimalPath(); + if (totalPath != null) { + if (!totalPath.isComponent()) { + printCriticalPathTimingBreakdown(totalPath, optimalPath); + } + } else { + lnPrint("Critical path not available because no action graph was generated."); + } + } + + 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)); + } + } + + /** + * Print total and optimal critical paths if available. + */ + public void printCriticalPaths() { + CriticalPathEntry totalPath = criticalPathStats.getTotalPath(); + printCriticalPath("Critical path", totalPath); + // In critical path components we do not record scheduling delay data so it does not make + // sense to differentiate it. + if (!totalPath.isComponent()) { + printCriticalPath( + "Critical path excluding scheduling delays", criticalPathStats.getOptimalPath()); + } + } + + 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); + } + } + } +} + + diff --git a/src/main/java/com/google/devtools/build/lib/profiler/output/HtmlCreator.java b/src/main/java/com/google/devtools/build/lib/profiler/output/HtmlCreator.java new file mode 100644 index 0000000000..45519cc183 --- /dev/null +++ b/src/main/java/com/google/devtools/build/lib/profiler/output/HtmlCreator.java @@ -0,0 +1,127 @@ +// 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.common.base.Optional; +import com.google.devtools.build.lib.profiler.ProfileInfo; +import com.google.devtools.build.lib.profiler.ProfilePhase; +import com.google.devtools.build.lib.profiler.chart.AggregatingChartCreator; +import com.google.devtools.build.lib.profiler.chart.Chart; +import com.google.devtools.build.lib.profiler.chart.ChartCreator; +import com.google.devtools.build.lib.profiler.chart.DetailedChartCreator; +import com.google.devtools.build.lib.profiler.chart.HtmlChartVisitor; +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.SkylarkStatistics; +import com.google.devtools.build.lib.vfs.Path; + +import java.io.BufferedOutputStream; +import java.io.IOException; +import java.io.PrintStream; +import java.util.EnumMap; + +/** + * Creates an HTML page displaying the various statistics and charts generated + * from the profile file. + */ +public final class HtmlCreator extends HtmlPrinter { + + private final Chart chart; + private final HtmlChartVisitor chartVisitor; + private final Optional<SkylarkHtml> skylarkStats; + private final String title; + private final PhaseHtml phases; + + private HtmlCreator( + PrintStream out, + String title, + Chart chart, + Optional<SkylarkHtml> skylarkStats, + int htmlPixelsPerSecond, + PhaseHtml phases) { + super(out); + this.title = title; + this.chart = chart; + chartVisitor = new HtmlChartVisitor(out, htmlPixelsPerSecond); + this.skylarkStats = skylarkStats; + this.phases = phases; + } + + private void print() { + htmlFrontMatter(); + chart.accept(chartVisitor); + + element("a", "name", "Statistics"); + element("h2", "Statistics"); + phases.print(); + + if (skylarkStats.isPresent()) { + skylarkStats.get().printHtmlBody(); + } + htmlBackMatter(); + } + + private void htmlFrontMatter() { + lnOpen("html"); + lnOpen("head"); + lnElement("title", title); + chartVisitor.printCss(chart.getSortedTypes()); + + phases.printCss(); + + if (skylarkStats.isPresent()) { + skylarkStats.get().printHtmlHead(); + } + + lnClose(); + lnOpen("body"); + lnElement("h1", title); + } + + private void htmlBackMatter() { + lnClose(); + lnClose(); + } + + /** + * Writes the HTML profiling information. + * + * @throws IOException + */ + public static void create( + ProfileInfo info, + Path htmlFile, + PhaseSummaryStatistics phaseSummaryStats, + EnumMap<ProfilePhase, PhaseStatistics> statistics, + boolean detailed, + int htmlPixelsPerSecond, + int vfsStatsLimit) + throws IOException { + try (PrintStream out = new PrintStream(new BufferedOutputStream(htmlFile.getOutputStream()))) { + ChartCreator chartCreator; + PhaseHtml phaseHtml = new PhaseHtml(out, phaseSummaryStats, statistics, vfsStatsLimit); + Optional<SkylarkHtml> skylarkStats; + if (detailed) { + skylarkStats = Optional.of(new SkylarkHtml(out, new SkylarkStatistics(info))); + chartCreator = new DetailedChartCreator(info); + } else { + chartCreator = new AggregatingChartCreator(info); + skylarkStats = Optional.absent(); + } + Chart chart = chartCreator.create(); + new HtmlCreator(out, info.comment, chart, skylarkStats, htmlPixelsPerSecond, phaseHtml) + .print(); + } + } +} diff --git a/src/main/java/com/google/devtools/build/lib/profiler/output/HtmlPrinter.java b/src/main/java/com/google/devtools/build/lib/profiler/output/HtmlPrinter.java new file mode 100644 index 0000000000..531e0f6fa0 --- /dev/null +++ b/src/main/java/com/google/devtools/build/lib/profiler/output/HtmlPrinter.java @@ -0,0 +1,104 @@ +// 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 java.io.PrintStream; +import java.util.ArrayDeque; +import java.util.Deque; + +/** + * Utility function for writing HTML data to a {@link PrintStream}. + */ +public abstract class HtmlPrinter extends TextPrinter { + + private Deque<String> currentlyOpenTags; + + protected HtmlPrinter(PrintStream out) { + super(out); + currentlyOpenTags = new ArrayDeque<>(); + } + + /** + * Print an open tag with attributes and possibly content and increase indentation level. + * + * <p>All array elements are taken in pairs for attributes and their values. If odd, the last + * element is taken as the content of the element. It is printed directly after the opening tag. + * @param attributesAndContent must have the form: attribute1, value1, attribute2, value2, ..., + * content + */ + protected void open(String tag, Object... attributesAndContent) { + printf("<%s", tag); + for (int index = 0; index < attributesAndContent.length - 1; index += 2) { + printf(" %s=\"%s\"", attributesAndContent[index], attributesAndContent[index + 1]); + } + print(">"); + if (attributesAndContent.length % 2 == 1) { + print(attributesAndContent[attributesAndContent.length - 1]); + } + down(); + currentlyOpenTags.addFirst(tag); + } + + /** + * Print a newline, an open tag with attributes and possibly content and increase indentation + * level + * @see #open(String, Object...) + */ + protected void lnOpen(String tag, Object... attributes) { + lnIndent(); + open(tag, attributes); + } + + /** + * Decrease indentation level and close the most recently opened tag + */ + protected void close() { + up(); + printf("</%s>", currentlyOpenTags.pop()); + } + + /** + * Decrease indentation level, print newline, indentation and close the most recently opened tag + */ + protected void lnClose() { + up(); + lnPrintf("</%s>", currentlyOpenTags.pop()); + } + + protected void lnElement(String tag, Object content) { + lnIndent(); + element(tag, content); + } + + /** + * Print a single element with attributes and possibly content. + * + * @see #open(String, Object...) + */ + protected void element(String tag, Object... attributesAndContent) { + open(tag, attributesAndContent); + close(); + } + + /** + * Print a newline, indent and a single element with attributes and possibly content. + * + * @see #lnOpen(String, Object...) + */ + protected void lnElement(String tag, Object... attributesAndContent) { + lnOpen(tag, attributesAndContent); + close(); + } +} + diff --git a/src/main/java/com/google/devtools/build/lib/profiler/output/PhaseHtml.java b/src/main/java/com/google/devtools/build/lib/profiler/output/PhaseHtml.java new file mode 100644 index 0000000000..f6e1cba255 --- /dev/null +++ b/src/main/java/com/google/devtools/build/lib/profiler/output/PhaseHtml.java @@ -0,0 +1,208 @@ +// 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.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.StringUtil; +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 HTML format. + */ +public final class PhaseHtml extends HtmlPrinter { + + private final PhaseSummaryStatistics phaseSummaryStats; + private final EnumMap<ProfilePhase, PhaseStatistics> phaseStatistics; + private final int vfsStatsLimit; + + /** + * @param vfsStatsLimit maximum number of VFS statistics to print, or -1 for no limit. + */ + public PhaseHtml( + PrintStream out, + PhaseSummaryStatistics phaseSummaryStats, + EnumMap<ProfilePhase, PhaseStatistics> phaseStatistics, + int vfsStatsLimit) { + super(out); + this.phaseSummaryStats = phaseSummaryStats; + this.phaseStatistics = phaseStatistics; + this.vfsStatsLimit = vfsStatsLimit; + } + + /** + * Output a style tag with all necessary CSS directives + */ + public void printCss() { + lnPrint("<style type=\"text/css\"><!--"); + down(); + lnPrint("div.phase-statistics {"); + lnPrint(" margin: 0 10;"); + lnPrint(" font-size: small;"); + lnPrint(" font-family: monospace;"); + lnPrint(" float: left;"); + lnPrint("}"); + lnPrint("table.phase-statistics {"); + lnPrint(" border: 0px; text-align: right;"); + lnPrint("}"); + lnPrint("table.phase-statistics td {"); + lnPrint(" padding: 0 5;"); + lnPrint("}"); + lnPrint("td.left {"); + lnPrint(" text-align: left;"); + lnPrint("}"); + lnPrint("td.center {"); + lnPrint(" text-align: center;"); + lnPrint("}"); + up(); + lnPrint("--></style>"); + } + + /** + * Print tables from {@link #phaseSummaryStats} and {@link #phaseStatistics} side by side. + */ + public void print() { + printPhaseSummaryStatistics(); + + for (ProfilePhase phase : + Arrays.asList(ProfilePhase.INIT, ProfilePhase.LOAD, ProfilePhase.ANALYZE)) { + PhaseStatistics statistics = phaseStatistics.get(phase); + if (!statistics.wasExecuted()) { + continue; + } + printPhaseStatistics(statistics); + } + lnElement("div", "style", "clear: both;"); + } + + /** + * Print header and tables for a single phase. + */ + private void printPhaseStatistics(PhaseStatistics phaseStat) { + lnOpen("div", "class", "phase-statistics"); + lnElement( + "h3", + String.format( + "%s Phase Information", StringUtil.capitalize(phaseStat.getProfilePhase().nick))); + lnOpen("table", "class", "phase-statistics"); + lnOpen("tr"); + open("td", "class", "left", "colspan", "3"); + printf("Total %s phase time", phaseStat.getProfilePhase().nick); + close(); // td + element("td", TimeUtilities.prettyTime(phaseStat.getPhaseDurationNanos())); + lnClose(); // tr + + if (!phaseStat.isEmpty()) { + lnOpen("tr"); + element("td", "class", "left", "colspan", "4", "Total time (across all threads) spent on:"); + close(); // tr + lnOpen("tr"); + element("td", "Type"); + element("td", "Total"); + element("td", "Count"); + element("td", "Average"); + close(); // tr + for (ProfilerTask taskType : phaseStat) { + lnOpen("tr", "class", "phase-task-statistics"); + element("td", taskType); + element("td", prettyPercentage(phaseStat.getTotalRelativeDuration(taskType))); + element("td", phaseStat.getCount(taskType)); + element("td", TimeUtilities.prettyTime(phaseStat.getMeanDuration(taskType))); + close(); // tr + } + } + lnClose(); // table + printVfsStatistics(phaseStat.getVfsStatistics()); + lnClose(); // div + } + + /** + * 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) { + if (vfsStatsLimit == 0 || stats.isEmpty()) { + return; + } + + lnElement("h4", "VFS path statistics:"); + + lnOpen("table", "class", "phase-statistics"); + lnOpen("tr"); + element("td", "Type"); + element("td", "Frequency"); + element("td", "Duration"); + element("td", "class", "left", "Path"); + close(); // tr + + for (ProfilerTask type : stats) { + int numPrinted = 0; + for (Entry<Stat, String> stat : stats.getSortedStatistics(type)) { + lnOpen("tr"); + if (vfsStatsLimit != -1 && numPrinted++ == vfsStatsLimit) { + open("td", "class", "center", "colspan", "4"); + printf("... %d more ...", stats.getStatisticsCount(type) - vfsStatsLimit); + close(); + close(); // tr + break; + } + element("td", type.name()); + element("td", stat.getKey().count); + element("td", TimeUtilities.prettyTime(stat.getKey().duration)); + element("td", "class", "left", stat.getValue()); + close(); // tr + } + } + + lnClose(); // table + } + + /** + * Print a table for the phase overview with runtime and runtime percentage per phase and total. + */ + private void printPhaseSummaryStatistics() { + lnOpen("div", "class", "phase-statistics"); + lnElement("h3", "Phase Summary Information"); + lnOpen("table", "class", "phase-statistics"); + for (ProfilePhase phase : phaseSummaryStats) { + lnOpen("tr"); + lnOpen("td", "class", "left"); + printf("Total %s phase time", phase.nick); + close(); + element("td", TimeUtilities.prettyTime(phaseSummaryStats.getDurationNanos(phase))); + element("td", phaseSummaryStats.getPrettyPercentage(phase)); + lnClose(); // tr + } + lnOpen("tr"); + lnElement("td", "class", "left", "Total run time"); + element("td", TimeUtilities.prettyTime(phaseSummaryStats.getTotalDuration())); + element("td", "100.00%"); + lnClose(); // tr + lnClose(); // table + lnClose(); // div + } +} + + 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()); + } + } + } +} + + diff --git a/src/main/java/com/google/devtools/build/lib/profiler/output/SkylarkHtml.java b/src/main/java/com/google/devtools/build/lib/profiler/output/SkylarkHtml.java new file mode 100644 index 0000000000..e073dde633 --- /dev/null +++ b/src/main/java/com/google/devtools/build/lib/profiler/output/SkylarkHtml.java @@ -0,0 +1,299 @@ +// 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.common.base.Joiner; +import com.google.common.base.StandardSystemProperty; +import com.google.common.collect.ListMultimap; +import com.google.devtools.build.lib.profiler.ProfileInfo.Task; +import com.google.devtools.build.lib.profiler.statistics.SkylarkStatistics; +import com.google.devtools.build.lib.profiler.statistics.TasksStatistics; + +import java.io.PrintStream; +import java.util.Arrays; +import java.util.List; + +/** + * Formats {@link SkylarkStatistics} as a HTML tables and histogram charts. + */ +public final class SkylarkHtml extends HtmlPrinter { + + /** + * How many characters from the end of the location of a Skylark function to display. + */ + private static final int NUM_LOCATION_CHARS_UNABBREVIATED = 40; + + private final SkylarkStatistics stats; + + public SkylarkHtml(PrintStream out, SkylarkStatistics stats) { + super(out); + this.stats = stats; + } + + /** + * Prints all CSS definitions and JavaScript code. May be a large amount of output. + */ + void printHtmlHead() { + lnOpen("style", "type", "text/css", "<!--"); + lnPrint("div.skylark-histogram {"); + lnPrint(" width: 95%; margin: 0 auto; display: none;"); + lnPrint("}"); + lnPrint("div.skylark-chart {"); + lnPrint(" width: 100%; height: 200px; margin: 0 auto 2em;"); + lnPrint("}"); + lnPrint("div.skylark-table {"); + lnPrint(" width: 95%; margin: 0 auto;"); + lnPrint("}"); + lnPrint("-->"); + close(); // style + + lnElement("script", "type", "text/javascript", "src", "https://www.google.com/jsapi"); + lnOpen("script", "type", "text/javascript"); + lnPrint("google.load(\"visualization\", \"1.1\", {packages:[\"corechart\",\"table\"]});"); + lnPrint("google.setOnLoadCallback(drawVisualization);"); + + String dataVar = "data"; + String tableVar = dataVar + "Table"; + lnPrintf("var %s = {};\n", dataVar); + lnPrintf("var %s = {};\n", tableVar); + lnPrint("var histogramData;"); + + lnPrint("function drawVisualization() {"); + down(); + printStatsJs( + stats.getUserFunctionStats(), "user", dataVar, tableVar, stats.getUserTotalNanos()); + printStatsJs( + stats.getBuiltinFunctionStats(), + "builtin", + dataVar, + tableVar, + stats.getBuiltinTotalNanos()); + + printHistogramData(); + + lnPrint("document.querySelector('#user-close').onclick = function() {"); + lnPrint(" document.querySelector('#user-histogram').style.display = 'none';"); + lnPrint("};"); + lnPrint("document.querySelector('#builtin-close').onclick = function() {"); + lnPrint(" document.querySelector('#builtin-histogram').style.display = 'none';"); + lnPrint("};"); + up(); + lnPrint("};"); + + lnPrint("var options = {"); + down(); + lnPrint("isStacked: true,"); + lnPrint("legend: { position: 'none' },"); + lnPrint("hAxis: { },"); + lnPrint("histogram: { lastBucketPercentile: 5 },"); + lnPrint("vAxis: { title: '# calls', viewWindowMode: 'pretty', gridlines: { count: -1 } }"); + up(); + lnPrint("};"); + + lnPrint("function selectHandler(category) {"); + down(); + lnPrint("return function() {"); + down(); + printf("var selection = %s[category].getSelection();", tableVar); + lnPrint("if (selection.length < 1) return;"); + lnPrint("var item = selection[0];"); + lnPrintf("var loc = %s[category].getValue(item.row, 0);", dataVar); + lnPrintf("var func = %s[category].getValue(item.row, 1);", dataVar); + lnPrint("var key = loc + '#' + func;"); + lnPrint("var histData = histogramData[category][key];"); + lnPrint("var fnOptions = JSON.parse(JSON.stringify(options));"); + lnPrint("fnOptions.title = loc + ' - ' + func;"); + lnPrint("var chartDiv = document.getElementById(category+'-chart');"); + lnPrint("var chart = new google.visualization.Histogram(chartDiv);"); + lnPrint("var histogramDiv = document.getElementById(category+'-histogram');"); + lnPrint("histogramDiv.style.display = 'block';"); + lnPrint("chart.draw(histData, fnOptions);"); + up(); + lnPrint("}"); + up(); + lnPrint("};"); + lnClose(); // script + } + + private void printHistogramData() { + lnPrint("histogramData = {"); + down(); + printHistogramData(stats.getBuiltinFunctionTasks(), "builtin"); + printHistogramData(stats.getUserFunctionTasks(), "user"); + up(); + lnPrint("}"); + } + + private void printHistogramData(ListMultimap<String, Task> tasks, String category) { + lnPrintf("'%s': {", category); + down(); + for (String function : tasks.keySet()) { + lnPrintf("'%s': google.visualization.arrayToDataTable(", function); + lnPrint("[['duration']"); + for (Task task : tasks.get(function)) { + printf(",[%f]", task.duration / 1000000.); + } + lnPrint("], false),"); + } + up(); + lnPrint("},"); + } + + private void printStatsJs( + List<TasksStatistics> statsList, + String category, + String dataVar, + String tableVar, + long totalNanos) { + String tmpVar = category + dataVar; + lnPrintf("var statsDiv = document.getElementById('%s_function_stats');", category); + if (statsList.isEmpty()) { + lnPrint( + "statsDiv.innerHTML = '<i>No relevant function calls to display. Some minor" + + " builtin functions may have been ignored because their names could not be used" + + " as variables in JavaScript.</i>'"); + } else { + lnPrintf("var %s = new google.visualization.DataTable();", tmpVar); + lnPrintf("%s.addColumn('string', 'Location');", tmpVar); + lnPrintf("%s.addColumn('string', 'Function');", tmpVar); + lnPrintf("%s.addColumn('number', 'count');", tmpVar); + lnPrintf("%s.addColumn('number', 'min (ms)');", tmpVar); + lnPrintf("%s.addColumn('number', 'mean (ms)');", tmpVar); + lnPrintf("%s.addColumn('number', 'median (ms)');", tmpVar); + lnPrintf("%s.addColumn('number', 'max (ms)');", tmpVar); + lnPrintf("%s.addColumn('number', 'std dev (ms)');", tmpVar); + lnPrintf("%s.addColumn('number', 'mean self (ms)');", tmpVar); + lnPrintf("%s.addColumn('number', 'self (ms)');", tmpVar); + lnPrintf("%s.addColumn('number', 'self (%%)');", tmpVar); + lnPrintf("%s.addColumn('number', 'total (ms)');", tmpVar); + lnPrintf("%s.addColumn('number', 'relative (%%)');", tmpVar); + lnPrintf("%s.addRows([", tmpVar); + down(); + for (TasksStatistics stats : statsList) { + double relativeTotal = (double) stats.totalNanos / totalNanos; + double relativeSelf = (double) stats.selfNanos / stats.totalNanos; + String[] split = stats.name.split("#"); + String location = split[0]; + String name = split[1]; + lnPrintf("[{v:'%s', f:'%s'}, ", location, abbreviatePath(location)); + printf("'%s', ", name); + printf("%d, ", stats.count); + printf("%.3f, ", stats.minimumMillis()); + printf("%.3f, ", stats.meanMillis()); + printf("%.3f, ", stats.medianMillis()); + printf("%.3f, ", stats.maximumMillis()); + printf("%.3f, ", stats.standardDeviationMillis); + printf("%.3f, ", stats.selfMeanMillis()); + printf("%.3f, ", stats.selfMillis()); + printf("{v:%.4f, f:'%.3f %%'}, ", relativeSelf, relativeSelf * 100); + printf("%.3f, ", stats.totalMillis()); + printf("{v:%.4f, f:'%.3f %%'}],", relativeTotal, relativeTotal * 100); + } + lnPrint("]);"); + up(); + lnPrintf("%s.%s = %s;", dataVar, category, tmpVar); + lnPrintf("%s.%s = new google.visualization.Table(statsDiv);", tableVar, category); + lnPrintf( + "google.visualization.events.addListener(%s.%s, 'select', selectHandler('%s'));", + tableVar, + category, + category); + lnPrintf( + "%s.%s.draw(%s.%s, {showRowNumber: true, width: '100%%', height: '100%%'});", + tableVar, + category, + dataVar, + category); + } + } + + /** + * Prints two sections for histograms and tables of statistics for user-defined and built-in + * Skylark functions. + */ + void printHtmlBody() { + lnPrint("<a name='skylark_stats'/>"); + lnElement("h3", "Skylark Statistics"); + lnElement("h4", "User-Defined function execution time"); + lnOpen("div", "class", "skylark-histogram", "id", "user-histogram"); + lnElement("div", "class", "skylark-chart", "id", "user-chart"); + lnElement("button", "id", "user-close", "Hide histogram"); + lnClose(); // div user-histogram + lnElement("div", "class", "skylark-table", "id", "user_function_stats"); + + lnElement("h4", "Builtin function execution time"); + lnOpen("div", "class", "skylark-histogram", "id", "builtin-histogram"); + lnElement("div", "class", "skylark-chart", "id", "builtin-chart"); + lnElement("button", "id", "builtin-close", "Hide histogram"); + lnClose(); // div builtin-histogram + lnElement("div", "class", "skylark-table", "id", "builtin_function_stats"); + } + + /** + * Computes a string keeping the structure of the input but reducing the amount of characters on + * elements at the front if necessary. + * + * <p>Reduces the length of function location strings by keeping at least the last element fully + * intact and at most {@link #NUM_LOCATION_CHARS_UNABBREVIATED} from other + * elements from the end. Elements before are abbreviated with their first two characters. + * + * <p>Example: + * "//source/tree/with/very/descriptive/and/long/hierarchy/of/directories/longfilename.bzl:42" + * becomes: "//so/tr/wi/ve/de/an/lo/hierarch/of/directories/longfilename.bzl:42" + * + * <p>There is no fixed length to the result as the last element is kept and the location may + * have many elements. + * + * @param location Either a sequence of path elements separated by + * {@link StandardSystemProperty#FILE_SEPARATOR} and preceded by some root element + * (e.g. "/", "C:\") or path elements separated by "." and having no root element. + */ + private String abbreviatePath(String location) { + String[] elements; + int lowestAbbreviateIndex; + String root; + String separator = StandardSystemProperty.FILE_SEPARATOR.value(); + if (location.contains(separator)) { + elements = location.split(separator); + // must take care to preserve file system roots (e.g. "/", "C:\"), keep separate + lowestAbbreviateIndex = 1; + root = location.substring(0, location.indexOf(separator) + 1); + } else { + // must be java class name for a builtin function + elements = location.split("\\."); + lowestAbbreviateIndex = 0; + root = ""; + separator = "."; + } + + String last = elements[elements.length - 1]; + int remaining = NUM_LOCATION_CHARS_UNABBREVIATED - last.length(); + // start from the next to last element of the location and add until "remaining" many + // chars added, abbreviate rest with first 2 characters + for (int index = elements.length - 2; index >= lowestAbbreviateIndex; index--) { + String element = elements[index]; + if (remaining > 0) { + int length = Math.min(remaining, element.length()); + element = element.substring(0, length); + remaining -= length; + } else { + element = element.substring(0, Math.min(2, element.length())); + } + elements[index] = element; + } + return root + Joiner.on(separator).join(Arrays.asList(elements).subList(1, elements.length)); + } +} + + diff --git a/src/main/java/com/google/devtools/build/lib/profiler/output/TextPrinter.java b/src/main/java/com/google/devtools/build/lib/profiler/output/TextPrinter.java new file mode 100644 index 0000000000..5b6413e88d --- /dev/null +++ b/src/main/java/com/google/devtools/build/lib/profiler/output/TextPrinter.java @@ -0,0 +1,111 @@ +// 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.common.base.Preconditions; + +import java.io.PrintStream; + +/** + * Utility function for writing text data to a {@link PrintStream}. + */ +public abstract class TextPrinter { + + protected static final String TWO_COLUMN_FORMAT = "%-37s %10s"; + protected static final String THREE_COLUMN_FORMAT = "%-28s %10s %8s"; + + private static final String INDENT = " "; + protected final PrintStream out; + private StringBuffer indent; + + protected TextPrinter(PrintStream out) { + this.out = out; + this.indent = new StringBuffer(); + } + + /** + * Increase indentation level + */ + protected void down() { + indent.append(INDENT); + } + + /** + * Decrease indentation level + */ + protected void up() { + Preconditions.checkState( + indent.length() >= INDENT.length(), + "Cannot reduce indentation level, this/a previous call to up() is not matched by down()."); + indent.setLength(indent.length() - INDENT.length()); + } + + protected void print(Object text) { + out.print(text); + } + + protected void printLn() { + out.println(); + } + + /** + * newline and indent by current indentation level + */ + protected void lnIndent() { + printLn(); + out.print(indent); + } + + /** + * newline, indent and print the Object + * @see PrintStream#print(Object) + */ + protected void lnPrint(Object text) { + lnIndent(); + out.print(text); + } + + /** + * print text and a newline + */ + protected void printLn(String text) { + out.print(text); + printLn(); + } + + /** + * newline, indent and print the formatted text + */ + protected void lnPrintf(String format, Object... args) { + lnIndent(); + out.printf(format, args); + } + + protected void printf(String format, Object... args) { + out.printf(format, args); + } + + /** + * Represents a double value as either "N/A" if it is NaN, or as a percentage with "%.2f%%". + * @param relativeValue is assumed to be a ratio of two values and will be multiplied with 100 + * for output + */ + public static String prettyPercentage(double relativeValue) { + if (Double.isNaN(relativeValue)) { + return "N/A"; + } + return String.format("%.2f%%", relativeValue * 100); + } +} + |