From 6bd4f2da3288a1508bdafe3072a1a2f611eb8316 Mon Sep 17 00:00:00 2001 From: Klaas Boesche Date: Tue, 22 Sep 2015 11:29:47 +0000 Subject: Heavily refactor ProfileCommand to separate output and statistics generation and enable their reuse -- MOS_MIGRATED_REVID=103634406 --- .../devtools/build/lib/profiler/ProfileInfo.java | 12 +- .../devtools/build/lib/profiler/ProfilerTask.java | 17 + .../build/lib/profiler/chart/HtmlCreator.java | 141 ------ .../lib/profiler/chart/SkylarkStatistics.java | 319 ------------ .../build/lib/profiler/chart/TasksStatistics.java | 142 ------ .../lib/profiler/output/CriticalPathText.java | 173 +++++++ .../build/lib/profiler/output/HtmlCreator.java | 127 +++++ .../build/lib/profiler/output/HtmlPrinter.java | 104 ++++ .../build/lib/profiler/output/PhaseHtml.java | 208 ++++++++ .../build/lib/profiler/output/PhaseText.java | 219 ++++++++ .../build/lib/profiler/output/SkylarkHtml.java | 299 +++++++++++ .../build/lib/profiler/output/TextPrinter.java | 111 ++++ .../statistics/CriticalPathStatistics.java | 215 ++++++++ .../lib/profiler/statistics/PhaseStatistics.java | 157 ++++++ .../statistics/PhaseSummaryStatistics.java | 100 ++++ .../profiler/statistics/PhaseVfsStatistics.java | 138 +++++ .../lib/profiler/statistics/SkylarkStatistics.java | 113 +++++ .../lib/profiler/statistics/TasksStatistics.java | 142 ++++++ .../build/lib/runtime/commands/ProfileCommand.java | 556 ++------------------- .../com/google/devtools/build/lib/sandbox/BUILD | 3 + .../com/google/devtools/build/lib/standalone/BUILD | 3 + .../devtools/build/lib/util/TimeUtilities.java | 2 +- .../com/google/devtools/build/lib/worker/BUILD | 2 + 23 files changed, 2171 insertions(+), 1132 deletions(-) delete mode 100644 src/main/java/com/google/devtools/build/lib/profiler/chart/HtmlCreator.java delete mode 100644 src/main/java/com/google/devtools/build/lib/profiler/chart/SkylarkStatistics.java delete mode 100644 src/main/java/com/google/devtools/build/lib/profiler/chart/TasksStatistics.java create mode 100644 src/main/java/com/google/devtools/build/lib/profiler/output/CriticalPathText.java create mode 100644 src/main/java/com/google/devtools/build/lib/profiler/output/HtmlCreator.java create mode 100644 src/main/java/com/google/devtools/build/lib/profiler/output/HtmlPrinter.java create mode 100644 src/main/java/com/google/devtools/build/lib/profiler/output/PhaseHtml.java create mode 100644 src/main/java/com/google/devtools/build/lib/profiler/output/PhaseText.java create mode 100644 src/main/java/com/google/devtools/build/lib/profiler/output/SkylarkHtml.java create mode 100644 src/main/java/com/google/devtools/build/lib/profiler/output/TextPrinter.java create mode 100644 src/main/java/com/google/devtools/build/lib/profiler/statistics/CriticalPathStatistics.java create mode 100644 src/main/java/com/google/devtools/build/lib/profiler/statistics/PhaseStatistics.java create mode 100644 src/main/java/com/google/devtools/build/lib/profiler/statistics/PhaseSummaryStatistics.java create mode 100644 src/main/java/com/google/devtools/build/lib/profiler/statistics/PhaseVfsStatistics.java create mode 100644 src/main/java/com/google/devtools/build/lib/profiler/statistics/SkylarkStatistics.java create mode 100644 src/main/java/com/google/devtools/build/lib/profiler/statistics/TasksStatistics.java (limited to 'src/main/java/com/google/devtools/build/lib') diff --git a/src/main/java/com/google/devtools/build/lib/profiler/ProfileInfo.java b/src/main/java/com/google/devtools/build/lib/profiler/ProfileInfo.java index d30b3dfd48..10f124f043 100644 --- a/src/main/java/com/google/devtools/build/lib/profiler/ProfileInfo.java +++ b/src/main/java/com/google/devtools/build/lib/profiler/ProfileInfo.java @@ -14,7 +14,6 @@ package com.google.devtools.build.lib.profiler; import static com.google.devtools.build.lib.profiler.ProfilerTask.CRITICAL_PATH; -import static com.google.devtools.build.lib.profiler.ProfilerTask.CRITICAL_PATH_COMPONENT; import static com.google.devtools.build.lib.profiler.ProfilerTask.TASK_COUNT; import com.google.common.base.Joiner; @@ -295,6 +294,15 @@ public class ProfileInfo { public long getCriticalTime() { return criticalTime; } + + /** + * @return true when this is just an action element on the critical path as logged by + * {@link com.google.devtools.build.lib.runtime.BuildSummaryStatsModule} and is thus a + * pre-processed and -analyzed critical path element + */ + public boolean isComponent() { + return task.type == ProfilerTask.CRITICAL_PATH_COMPONENT; + } } /** @@ -760,7 +768,7 @@ public class ProfileInfo { public void analyzeCriticalPath(Set ignoredTypes, CriticalPathEntry path) { // With light critical path we do not need to analyze since it is already preprocessed // by blaze build. - if (path != null && path.task.type == CRITICAL_PATH_COMPONENT) { + if (path == null || path.isComponent()) { return; } for (CriticalPathEntry entry = path; entry != null; entry = entry.next) { diff --git a/src/main/java/com/google/devtools/build/lib/profiler/ProfilerTask.java b/src/main/java/com/google/devtools/build/lib/profiler/ProfilerTask.java index 37349b1406..00e2557351 100644 --- a/src/main/java/com/google/devtools/build/lib/profiler/ProfilerTask.java +++ b/src/main/java/com/google/devtools/build/lib/profiler/ProfilerTask.java @@ -13,6 +13,10 @@ // limitations under the License. package com.google.devtools.build.lib.profiler; +import com.google.common.base.Predicate; + +import java.util.EnumSet; + /** * All possible types of profiler tasks. Each type also defines description and * minimum duration in nanoseconds for it to be recorded as separate event and @@ -115,4 +119,17 @@ public enum ProfilerTask { public boolean collectsSlowestInstances() { return slowestInstancesCount > 0; } + + /** + * Build a set containing all ProfilerTasks for which the given predicate is true. + */ + public static EnumSet allSatisfying(Predicate predicate) { + EnumSet set = EnumSet.noneOf(ProfilerTask.class); + for (ProfilerTask taskType : values()) { + if (predicate.apply(taskType)) { + set.add(taskType); + } + } + return set; + } } diff --git a/src/main/java/com/google/devtools/build/lib/profiler/chart/HtmlCreator.java b/src/main/java/com/google/devtools/build/lib/profiler/chart/HtmlCreator.java deleted file mode 100644 index 899e339d4c..0000000000 --- a/src/main/java/com/google/devtools/build/lib/profiler/chart/HtmlCreator.java +++ /dev/null @@ -1,141 +0,0 @@ -// 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.chart; - -import com.google.common.base.Optional; -import com.google.devtools.build.lib.profiler.ProfileInfo; -import com.google.devtools.build.lib.profiler.ProfilePhaseStatistics; -import com.google.devtools.build.lib.vfs.Path; - -import java.io.BufferedOutputStream; -import java.io.IOException; -import java.io.PrintStream; -import java.util.List; - -/** - * Creates an HTML page displaying the various statistics and charts generated - * from the profile file. - */ -public final class HtmlCreator { - - private final PrintStream out; - private final Chart chart; - private final HtmlChartVisitor chartVisitor; - private final Optional skylarkStats; - private final String title; - - /** - * Pre-formatted statistics for each phase of the profiled build. - */ - private final List statistics; - - private HtmlCreator( - PrintStream out, - String title, - Chart chart, - Optional skylarkStats, - int htmlPixelsPerSecond, - List statistics) { - this.out = out; - this.title = title; - this.chart = chart; - chartVisitor = new HtmlChartVisitor(out, htmlPixelsPerSecond); - this.skylarkStats = skylarkStats; - this.statistics = statistics; - } - - private void print() { - htmlFrontMatter(); - chart.accept(chartVisitor); - - out.println("

Statistics

"); - printPhaseStatistics(); - - if (skylarkStats.isPresent()) { - skylarkStats.get().printHtmlBody(); - } - htmlBackMatter(); - } - - private void htmlFrontMatter() { - out.println(""); - out.printf("%s", title); - chartVisitor.printCss(chart.getSortedTypes()); - - if (skylarkStats.isPresent()) { - skylarkStats.get().printHtmlHead(); - } - - out.println(""); - out.println(""); - out.printf("

%s

\n", title); - } - - private void htmlBackMatter() { - out.println(""); - out.println(""); - } - - /** - * Print a table from {@link #statistics} arranging the phases side by side. - */ - private void printPhaseStatistics() { - out.println(""); - String statsSeparator = ""; - for (ProfilePhaseStatistics stat : statistics) { - out.println(statsSeparator); - out.println(""); - statsSeparator = ""; - } - out.println("
"); - String title = stat.getTitle(); - if (!title.isEmpty()) { - out.println(String.format("

%s

", title)); - } - out.println("
" + stat.getStatistics() + "
 
"); - } - - /** - * Writes the HTML profiling information. - * @param info - * @param htmlFile - * @param statistics - * @param detailed - * @param htmlPixelsPerSecond - * @throws IOException - */ - public static void createHtml( - ProfileInfo info, - Path htmlFile, - List statistics, - boolean detailed, - int htmlPixelsPerSecond) - throws IOException { - try (PrintStream out = new PrintStream(new BufferedOutputStream(htmlFile.getOutputStream()))) { - ChartCreator chartCreator; - Optional skylarkStats; - if (detailed) { - chartCreator = new DetailedChartCreator(info); - skylarkStats = Optional.of(new SkylarkStatistics(out, info)); - } else { - chartCreator = new AggregatingChartCreator(info); - skylarkStats = Optional.absent(); - } - Chart chart = chartCreator.create(); - new HtmlCreator(out, info.comment, chart, skylarkStats, htmlPixelsPerSecond, statistics) - .print(); - } - } -} diff --git a/src/main/java/com/google/devtools/build/lib/profiler/chart/SkylarkStatistics.java b/src/main/java/com/google/devtools/build/lib/profiler/chart/SkylarkStatistics.java deleted file mode 100644 index ce3376aac2..0000000000 --- a/src/main/java/com/google/devtools/build/lib/profiler/chart/SkylarkStatistics.java +++ /dev/null @@ -1,319 +0,0 @@ -// 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.chart; - -import com.google.common.base.Joiner; -import com.google.common.base.StandardSystemProperty; -import com.google.common.collect.ListMultimap; -import com.google.common.collect.Multimaps; -import com.google.devtools.build.lib.profiler.ProfileInfo; -import com.google.devtools.build.lib.profiler.ProfileInfo.Task; - -import java.io.PrintStream; -import java.util.ArrayList; -import java.util.Arrays; -import java.util.List; -import java.util.Map.Entry; - -/** - * Computes various statistics for Skylark and built-in function usage and prints it to a given - * {@link PrintStream}. - */ -public final class SkylarkStatistics { - - /** - * 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 ListMultimap userFunctionTasks; - private final ListMultimap builtinFunctionTasks; - private final List userFunctionStats; - private final List builtinFunctionStats; - private long userTotalNanos; - private long builtinTotalNanos; - - private final PrintStream out; - - public SkylarkStatistics(PrintStream out, ProfileInfo info) { - this.out = out; - userFunctionTasks = info.getSkylarkUserFunctionTasks(); - builtinFunctionTasks = info.getSkylarkBuiltinFunctionTasks(); - userFunctionStats = new ArrayList<>(); - builtinFunctionStats = new ArrayList<>(); - computeStatistics(); - } - - /** - * For each Skylark function compute a {@link TasksStatistics} object from the execution times of - * all corresponding {@link Task}s from either {@link #userFunctionTasks} or - * {@link #builtinFunctionTasks}. Fills fields {@link #userFunctionStats} and - * {@link #builtinFunctionStats}. - */ - private void computeStatistics() { - userTotalNanos = computeStatistics(userFunctionTasks, userFunctionStats); - builtinTotalNanos = computeStatistics(builtinFunctionTasks, builtinFunctionStats); - } - - /** - * For each Skylark function compute a {@link TasksStatistics} object from the execution times of - * all corresponding {@link Task}s and add it to the list. - * @param tasks Map from function name to all corresponding tasks. - * @param stats The list to which {@link TasksStatistics} are to be added. - * @return The sum of the execution times of all {@link Task} values in the map. - */ - private static long computeStatistics( - ListMultimap tasks, List stats) { - long total = 0L; - for (Entry> entry : Multimaps.asMap(tasks).entrySet()) { - TasksStatistics functionStats = TasksStatistics.create(entry.getKey(), entry.getValue()); - stats.add(functionStats); - total += functionStats.totalNanos; - } - return total; - } - - /** - * Prints all CSS definitions and JavaScript code. May be a large amount of output. - */ - void printHtmlHead() { - out.println(""); - - out.println(""); - out.println(""); - } - - private void printHistogramData() { - out.println(" histogramData = {"); - printHistogramData(builtinFunctionTasks, "builtin"); - printHistogramData(userFunctionTasks, "user"); - out.println(" }"); - } - - private void printHistogramData(ListMultimap tasks, String category) { - out.printf(" '%s': {\n", category); - for (String function : tasks.keySet()) { - out.printf(" '%s': google.visualization.arrayToDataTable(\n", function); - out.print(" [['duration']"); - for (Task task : tasks.get(function)) { - out.printf(",[%f]", task.duration / 1000000.); - } - out.println("],\n false),"); - } - out.println(" },"); - } - - private void printStatsJs( - List statsList, - String category, - String dataVar, - String tableVar, - long totalNanos) { - String tmpVar = category + dataVar; - out.printf(" var statsDiv = document.getElementById('%s_function_stats');\n", category); - if (statsList.isEmpty()) { - out.println(" statsDiv.innerHTML = '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.'"); - } else { - out.printf(" var %s = new google.visualization.DataTable();\n", tmpVar); - out.printf(" %s.addColumn('string', 'Location');\n", tmpVar); - out.printf(" %s.addColumn('string', 'Function');\n", tmpVar); - out.printf(" %s.addColumn('number', 'count');\n", tmpVar); - out.printf(" %s.addColumn('number', 'min (ms)');\n", tmpVar); - out.printf(" %s.addColumn('number', 'mean (ms)');\n", tmpVar); - out.printf(" %s.addColumn('number', 'median (ms)');\n", tmpVar); - out.printf(" %s.addColumn('number', 'max (ms)');\n", tmpVar); - out.printf(" %s.addColumn('number', 'std dev (ms)');\n", tmpVar); - out.printf(" %s.addColumn('number', 'mean self (ms)');\n", tmpVar); - out.printf(" %s.addColumn('number', 'self (ms)');\n", tmpVar); - out.printf(" %s.addColumn('number', 'self (%%)');\n", tmpVar); - out.printf(" %s.addColumn('number', 'total (ms)');\n", tmpVar); - out.printf(" %s.addColumn('number', 'relative (%%)');\n", tmpVar); - out.printf(" %s.addRows([\n", tmpVar); - 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]; - out.printf(" [{v:'%s', f:'%s'}, ", location, abbreviatePath(location)); - out.printf("'%s', ", name); - out.printf("%d, ", stats.count); - out.printf("%.3f, ", stats.minimumMillis()); - out.printf("%.3f, ", stats.meanMillis()); - out.printf("%.3f, ", stats.medianMillis()); - out.printf("%.3f, ", stats.maximumMillis()); - out.printf("%.3f, ", stats.standardDeviationMillis); - out.printf("%.3f, ", stats.selfMeanMillis()); - out.printf("%.3f, ", stats.selfMillis()); - out.printf("{v:%.4f, f:'%.3f %%'}, ", relativeSelf, relativeSelf * 100); - out.printf("%.3f, ", stats.totalMillis()); - out.printf("{v:%.4f, f:'%.3f %%'}],\n", relativeTotal, relativeTotal * 100); - } - out.println(" ]);"); - out.printf(" %s.%s = %s;\n", dataVar, category, tmpVar); - out.printf(" %s.%s = new google.visualization.Table(statsDiv);\n", tableVar, category); - out.printf( - " google.visualization.events.addListener(%s.%s, 'select', selectHandler('%s'));\n", - tableVar, - category, - category); - out.printf( - " %s.%s.draw(%s.%s, {showRowNumber: true, width: '100%%', height: '100%%'});\n", - tableVar, - category, - dataVar, - category); - } - } - - /** - * Prints two sections for histograms and tables of statistics for user-defined and built-in - * Skylark functions. - */ - void printHtmlBody() { - out.println(""); - out.println("

Skylark Statistics

"); - out.println("

User-Defined function execution time

"); - out.println("
"); - out.println("
"); - out.println(" "); - out.println("
"); - out.println("
"); - - out.println("

Builtin function execution time

"); - out.println("
"); - out.println("
"); - out.println(" "); - out.println("
"); - out.println("
"); - } - - /** - * Computes a string keeping the structure of the input but reducing the amount of characters on - * elements at the front if necessary. - * - *

Reduces the length of function location strings by keeping at least the last element fully - * intact and at most {@link SkylarkStatistics#NUM_LOCATION_CHARS_UNABBREVIATED} from other - * elements from the end. Elements before are abbreviated with their first two characters. - * - *

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" - * - *

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/chart/TasksStatistics.java b/src/main/java/com/google/devtools/build/lib/profiler/chart/TasksStatistics.java deleted file mode 100644 index 0731118a08..0000000000 --- a/src/main/java/com/google/devtools/build/lib/profiler/chart/TasksStatistics.java +++ /dev/null @@ -1,142 +0,0 @@ -// 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.chart; - -import com.google.devtools.build.lib.profiler.ProfileInfo.Task; - -import java.util.Collections; -import java.util.Comparator; -import java.util.List; - -/** - * Data container to aggregate execution time statistics of multiple tasks grouped by some name. - */ -class TasksStatistics { - public final String name; - public final int count; - public final long minNanos; - public final long maxNanos; - public final double medianNanos; - /** Standard deviation of the execution time in milliseconds since computation in nanoseconds can - * overflow. - */ - public final double standardDeviationMillis; - public final long totalNanos; - public final long selfNanos; - - public TasksStatistics( - String name, - int count, - long minNanos, - long maxNanos, - double medianNanos, - double standardDeviationMillis, - long totalNanos, - long selfNanos) { - this.name = name; - this.count = count; - this.minNanos = minNanos; - this.maxNanos = maxNanos; - this.medianNanos = medianNanos; - this.standardDeviationMillis = standardDeviationMillis; - this.totalNanos = totalNanos; - this.selfNanos = selfNanos; - } - - public double minimumMillis() { - return toMilliSeconds(minNanos); - } - - public double maximumMillis() { - return toMilliSeconds(maxNanos); - } - - public double meanNanos() { - return totalNanos / count; - } - - public double meanMillis() { - return toMilliSeconds(meanNanos()); - } - - public double medianMillis() { - return toMilliSeconds(medianNanos); - } - - public double totalMillis() { - return toMilliSeconds(totalNanos); - } - - public double selfMillis() { - return toMilliSeconds(selfNanos); - } - - public double selfMeanNanos() { - return selfNanos / count; - } - - public double selfMeanMillis() { - return toMilliSeconds(selfMeanNanos()); - } - - /** - * @param name - * @param tasks - * @return The set of statistics grouped in this class, computed from a list of {@link Task}s. - */ - public static TasksStatistics create(String name, List tasks) { - Collections.sort( - tasks, - new Comparator() { - @Override - public int compare(Task o1, Task o2) { - return Long.compare(o1.duration, o2.duration); - } - }); - int count = tasks.size(); - long min = tasks.get(0).duration; - long max = tasks.get(count - 1).duration; - - int midIndex = count / 2; - double median = - tasks.size() % 2 == 0 - ? (tasks.get(midIndex).duration + tasks.get(midIndex - 1).duration) / 2.0 - : tasks.get(midIndex).duration; - - // Compute standard deviation with a shift to avoid catastrophic cancellation - // and also do it in milliseconds, as in nanoseconds it overflows - long sum = 0L; - long self = 0L; - double sumOfSquaredShiftedMillis = 0L; - final long shift = min; - - for (Task task : tasks) { - sum += task.duration; - self += task.duration - task.getInheritedDuration(); - double taskDurationShiftMillis = toMilliSeconds(task.duration - shift); - sumOfSquaredShiftedMillis += taskDurationShiftMillis * taskDurationShiftMillis; - } - double sumShiftedMillis = toMilliSeconds(sum - count * shift); - - double standardDeviation = - Math.sqrt( - (sumOfSquaredShiftedMillis - (sumShiftedMillis * sumShiftedMillis) / count) / count); - - return new TasksStatistics(name, count, min, max, median, standardDeviation, sum, self); - } - - static double toMilliSeconds(double nanoseconds) { - return nanoseconds / 1000000.0; - } -} 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 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 skylarkStats; + private final String title; + private final PhaseHtml phases; + + private HtmlCreator( + PrintStream out, + String title, + Chart chart, + Optional 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 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 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 currentlyOpenTags; + + protected HtmlPrinter(PrintStream out) { + super(out); + currentlyOpenTags = new ArrayDeque<>(); + } + + /** + * Print an open tag with attributes and possibly content and increase indentation level. + * + *

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("", currentlyOpenTags.pop()); + } + + /** + * Decrease indentation level, print newline, indentation and close the most recently opened tag + */ + protected void lnClose() { + up(); + lnPrintf("", 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 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 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(""); + } + + /** + * 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 : 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 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 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 : 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", ""); + 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 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 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 = '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.'"); + } 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(""); + 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. + * + *

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. + * + *

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" + * + *

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); + } +} + diff --git a/src/main/java/com/google/devtools/build/lib/profiler/statistics/CriticalPathStatistics.java b/src/main/java/com/google/devtools/build/lib/profiler/statistics/CriticalPathStatistics.java new file mode 100644 index 0000000000..72262a8d18 --- /dev/null +++ b/src/main/java/com/google/devtools/build/lib/profiler/statistics/CriticalPathStatistics.java @@ -0,0 +1,215 @@ +// 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.statistics; + +import com.google.common.base.Predicate; +import com.google.devtools.build.lib.profiler.ProfileInfo; +import com.google.devtools.build.lib.profiler.ProfileInfo.CriticalPathEntry; +import com.google.devtools.build.lib.profiler.ProfileInfo.Task; +import com.google.devtools.build.lib.profiler.ProfilePhase; +import com.google.devtools.build.lib.profiler.ProfilerTask; +import com.google.devtools.build.lib.util.Pair; + +import java.util.ArrayList; +import java.util.Arrays; +import java.util.Collections; +import java.util.EnumSet; +import java.util.Iterator; +import java.util.List; + +/** + * Keeps a predefined list of {@link CriticalPathEntry}'s cumulative durations and allows + * iterating over pairs of their descriptions and relative durations. + */ +//TODO(bazel-team): Add remote vs build stats recorded by Logging.CriticalPathStats +public final class CriticalPathStatistics implements Iterable> { + + private static final EnumSet FILTER_NONE = EnumSet.noneOf(ProfilerTask.class); + /** Always filter out ACTION_LOCK and WAIT tasks to simulate unlimited resource critical path + * (TODO see comments inside formatExecutionPhaseStatistics() method). + */ + private static final EnumSet DEFAULT_FILTER = + EnumSet.of(ProfilerTask.ACTION_LOCK, ProfilerTask.WAIT); + + private static final List>> FILTERS = + Arrays.asList( + Pair.of("the builder overhead", EnumSet.allOf(ProfilerTask.class)), + Pair.of( + "the VFS calls", + ProfilerTask.allSatisfying( + new Predicate() { + @Override + public boolean apply(ProfilerTask task) { + return DEFAULT_FILTER.contains(task) || task.name().startsWith("VFS_"); + } + })), + typeFilter("the dependency checking", ProfilerTask.ACTION_CHECK), + typeFilter("the execution setup", ProfilerTask.ACTION_EXECUTE), + typeFilter("local execution", ProfilerTask.SPAWN, ProfilerTask.LOCAL_EXECUTION), + typeFilter("the include scanner", ProfilerTask.SCANNER), + typeFilter( + "Remote execution (cumulative)", + ProfilerTask.REMOTE_EXECUTION, + ProfilerTask.PROCESS_TIME, + ProfilerTask.LOCAL_PARSE, + ProfilerTask.UPLOAD_TIME, + ProfilerTask.REMOTE_QUEUE, + ProfilerTask.REMOTE_SETUP, + ProfilerTask.FETCH), + typeFilter(" file uploads", ProfilerTask.UPLOAD_TIME, ProfilerTask.REMOTE_SETUP), + typeFilter(" file fetching", ProfilerTask.FETCH), + typeFilter(" process time", ProfilerTask.PROCESS_TIME), + typeFilter(" remote queueing", ProfilerTask.REMOTE_QUEUE), + typeFilter(" remote execution parse", ProfilerTask.LOCAL_PARSE), + typeFilter(" other remote activities", ProfilerTask.REMOTE_EXECUTION)); + + private final List criticalPathDurations; + + /** + * The actual critical path. + */ + private final CriticalPathEntry totalPath; + + /** + * Unlimited resource critical path. Essentially, we assume that if we remove all scheduling + * delays caused by resource semaphore contention, each action execution time would not change + * (even though load now would be substantially higher - so this assumption might be incorrect + * but it is the path excluding scheduling delays). + */ + private final CriticalPathEntry optimalPath; + + private final long workerWaitTime; + private final long mainThreadWaitTime; + + /** + * Only call this constructor if {@link ProfilePhase#EXECUTE} was actually run. + */ + public CriticalPathStatistics(ProfileInfo info) { + totalPath = info.getCriticalPath(FILTER_NONE); + info.analyzeCriticalPath(FILTER_NONE, totalPath); + + optimalPath = info.getCriticalPath(DEFAULT_FILTER); + info.analyzeCriticalPath(DEFAULT_FILTER, optimalPath); + + if (totalPath.isComponent()) { + this.workerWaitTime = 0; + this.mainThreadWaitTime = 0; + criticalPathDurations = Collections.emptyList(); + return; + } + // Worker thread pool scheduling delays for the actual critical path. + long workerWaitTime = 0; + long mainThreadWaitTime = 0; + for (CriticalPathEntry entry = totalPath; entry != null; entry = entry.next) { + workerWaitTime += info.getActionWaitTime(entry.task); + mainThreadWaitTime += info.getActionQueueTime(entry.task); + } + this.workerWaitTime = workerWaitTime; + this.mainThreadWaitTime = mainThreadWaitTime; + + criticalPathDurations = getCriticalPathDurations(info); + } + + /** + * @return the critical path obtained by not filtering out any {@link ProfilerTask} + */ + public CriticalPathEntry getTotalPath() { + return totalPath; + } + + /** + * @return the critical path obtained by filtering out any lock and wait tasks (see + * {@link #DEFAULT_FILTER}) + */ + public CriticalPathEntry getOptimalPath() { + return optimalPath; + } + + /** + * @see ProfileInfo#getActionWaitTime(Task) + * @return the sum of all action wait times on the total critical path + */ + public long getWorkerWaitTime() { + return workerWaitTime; + } + + /** + * @see ProfileInfo#getActionQueueTime(Task) + * @return the mainThreadWaitTime + */ + public long getMainThreadWaitTime() { + return mainThreadWaitTime; + } + + @Override + public Iterator> iterator() { + return new Iterator>() { + + Iterator durations = criticalPathDurations.iterator(); + Iterator>> filters = FILTERS.iterator(); + boolean overheadFilter = true; + + @Override + public boolean hasNext() { + return durations.hasNext(); + } + + @Override + public Pair next() { + long duration = durations.next(); + String description = filters.next().first; + double relativeDuration; + if (overheadFilter) { + overheadFilter = false; + relativeDuration = (double) duration / totalPath.cumulativeDuration; + } else { + relativeDuration = + (double) (optimalPath.cumulativeDuration - duration) / optimalPath.cumulativeDuration; + } + return Pair.of(description, relativeDuration); + } + + @Override + public void remove() { + throw new UnsupportedOperationException(); + } + }; + } + + /** + * Extract all {@link CriticalPathEntry} durations for the filters defined by {@link #FILTERS}. + */ + private static List getCriticalPathDurations(ProfileInfo info) { + List list = new ArrayList<>(FILTERS.size()); + + for (Pair> filter : FILTERS) { + list.add(info.getCriticalPath(filter.second).cumulativeDuration); + } + return list; + } + + /** + * Returns set of profiler tasks to be filtered from critical path. + * Also always filters out ACTION_LOCK and WAIT tasks to simulate + * unlimited resource critical path (see comments inside formatExecutionPhaseStatistics() + * method). + */ + private static Pair> typeFilter( + String description, ProfilerTask... tasks) { + EnumSet filter = EnumSet.of(ProfilerTask.ACTION_LOCK, ProfilerTask.WAIT); + Collections.addAll(filter, tasks); + return Pair.of(description, filter); + } +} + diff --git a/src/main/java/com/google/devtools/build/lib/profiler/statistics/PhaseStatistics.java b/src/main/java/com/google/devtools/build/lib/profiler/statistics/PhaseStatistics.java new file mode 100644 index 0000000000..c5bbd7b6e9 --- /dev/null +++ b/src/main/java/com/google/devtools/build/lib/profiler/statistics/PhaseStatistics.java @@ -0,0 +1,157 @@ +// 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.statistics; + +import com.google.common.base.Predicate; +import com.google.common.collect.Iterators; +import com.google.devtools.build.lib.profiler.ProfileInfo; +import com.google.devtools.build.lib.profiler.ProfileInfo.AggregateAttr; +import com.google.devtools.build.lib.profiler.ProfileInfo.Task; +import com.google.devtools.build.lib.profiler.ProfilePhase; +import com.google.devtools.build.lib.profiler.ProfilerTask; + +import java.util.EnumMap; +import java.util.Iterator; +import java.util.List; + +/** + * Extracts and keeps statistics for one {@link ProfilePhase} for formatting to various outputs. + */ +public final class PhaseStatistics implements Iterable { + + private final ProfilePhase phase; + private final long phaseDurationNanos; + private final long totalDurationNanos; + private final EnumMap aggregateTaskStatistics; + private final PhaseVfsStatistics vfsStatistics; + private final boolean wasExecuted; + + public PhaseStatistics(ProfilePhase phase, ProfileInfo info, String workSpaceName) { + this.phase = phase; + this.aggregateTaskStatistics = new EnumMap<>(ProfilerTask.class); + Task phaseTask = info.getPhaseTask(phase); + vfsStatistics = new PhaseVfsStatistics(workSpaceName, phase, info); + if (phaseTask == null) { + wasExecuted = false; + totalDurationNanos = 0; + phaseDurationNanos = 0; + } else { + wasExecuted = true; + phaseDurationNanos = info.getPhaseDuration(phaseTask); + List taskList = info.getTasksForPhase(phaseTask); + long duration = phaseDurationNanos; + for (Task task : taskList) { + // Tasks on the phaseTask thread already accounted for in the phaseDuration. + if (task.threadId != phaseTask.threadId) { + duration += task.duration; + } + } + totalDurationNanos = duration; + for (ProfilerTask type : ProfilerTask.values()) { + aggregateTaskStatistics.put(type, info.getStatsForType(type, taskList)); + } + } + } + + public ProfilePhase getProfilePhase() { + return phase; + } + + public PhaseVfsStatistics getVfsStatistics() { + return vfsStatistics; + } + + /** + * @return true if no {@link ProfilerTask}s have been executed in this phase, false otherwise + */ + public boolean isEmpty() { + return aggregateTaskStatistics.isEmpty(); + } + + /** + * @return true if the phase was not executed at all, false otherwise + */ + public boolean wasExecuted() { + return wasExecuted; + } + + public long getPhaseDurationNanos() { + return phaseDurationNanos; + } + + public long getTotalDurationNanos() { + return totalDurationNanos; + } + + /** + * @return true if a task of the given {@link ProfilerTask} type was executed in this phase + */ + public boolean wasExecuted(ProfilerTask taskType) { + return aggregateTaskStatistics.get(taskType).count != 0; + } + + /** + * @return the sum of all task durations of the given type + */ + public long getTotalDurationNanos(ProfilerTask taskType) { + return aggregateTaskStatistics.get(taskType).totalTime; + } + + /** + * @return the average duration of all {@link ProfilerTask} + */ + public double getMeanDuration(ProfilerTask taskType) { + if (wasExecuted(taskType)) { + AggregateAttr stats = aggregateTaskStatistics.get(taskType); + return (double) stats.totalTime / stats.count; + } + return 0; + } + + /** + * @return the duration of all {@link ProfilerTask} executed in the phase relative to the total + * phase duration + */ + public double getTotalRelativeDuration(ProfilerTask taskType) { + if (wasExecuted(taskType)) { + return (double) aggregateTaskStatistics.get(taskType).totalTime / totalDurationNanos; + } + return 0; + } + + /** + * @return how many tasks of the given type were executed in this phase + */ + public int getCount(ProfilerTask taskType) { + return aggregateTaskStatistics.get(taskType).count; + } + + /** + * Iterator over all {@link ProfilerTask}s that were executed at least once and have a total + * duration greater than 0. + */ + @Override + public Iterator iterator() { + return Iterators.filter( + aggregateTaskStatistics.keySet().iterator(), + new Predicate() { + @Override + public boolean apply(ProfilerTask taskType) { + + return getTotalDurationNanos(taskType) != 0 && getCount(taskType) != 0; + } + }); + } +} + diff --git a/src/main/java/com/google/devtools/build/lib/profiler/statistics/PhaseSummaryStatistics.java b/src/main/java/com/google/devtools/build/lib/profiler/statistics/PhaseSummaryStatistics.java new file mode 100644 index 0000000000..c9848ca8b2 --- /dev/null +++ b/src/main/java/com/google/devtools/build/lib/profiler/statistics/PhaseSummaryStatistics.java @@ -0,0 +1,100 @@ +// 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.statistics; + +import com.google.devtools.build.lib.profiler.ProfileInfo; +import com.google.devtools.build.lib.profiler.ProfilePhase; + +import java.util.EnumMap; +import java.util.Iterator; +import java.util.NoSuchElementException; + +/** + * Extracts and keeps summary statistics from all {@link ProfilePhase}s for formatting to various + * outputs. + */ +public final class PhaseSummaryStatistics implements Iterable { + + private final long totalDurationNanos; + private final EnumMap durations; + + public PhaseSummaryStatistics(ProfileInfo info) { + durations = new EnumMap<>(ProfilePhase.class); + long totalDuration = 0; + for (ProfilePhase phase : ProfilePhase.values()) { + ProfileInfo.Task phaseTask = info.getPhaseTask(phase); + if (phaseTask != null) { + long phaseDuration = info.getPhaseDuration(phaseTask); + totalDuration += phaseDuration; + durations.put(phase, phaseDuration); + } + } + totalDurationNanos = totalDuration; + } + + /** + * @return whether the given {@link ProfilePhase} was executed + */ + public boolean contains(ProfilePhase phase) { + return durations.containsKey(phase); + } + + /** + * @return the execution duration of a given {@link ProfilePhase} + * @throws NoSuchElementException if the given {@link ProfilePhase} was not executed + */ + public long getDurationNanos(ProfilePhase phase) { + checkContains(phase); + return durations.get(phase); + } + + /** + * @return The duration of the phase relative to the sum of all phase durations + * @throws NoSuchElementException if the given {@link ProfilePhase} was not executed + */ + public double getRelativeDuration(ProfilePhase phase) { + checkContains(phase); + return (double) getDurationNanos(phase) / totalDurationNanos; + } + + /** + * Converts {@link #getRelativeDuration(ProfilePhase)} to a percentage string + * @return formatted percentage string ("%.2f%%") or "N/A" when totalNanos is 0. + * @throws NoSuchElementException if the given {@link ProfilePhase} was not executed + */ + public String getPrettyPercentage(ProfilePhase phase) { + checkContains(phase); + if (totalDurationNanos == 0) { + // Return "not available" string if total is 0 and result is undefined. + return "N/A"; + } + return String.format("%.2f%%", getRelativeDuration(phase) * 100); + } + + public long getTotalDuration() { + return totalDurationNanos; + } + + @Override + public Iterator iterator() { + return durations.keySet().iterator(); + } + + private void checkContains(ProfilePhase phase) { + if (!contains(phase)) { + throw new NoSuchElementException("Phase " + phase + " was not executed"); + } + } +} + diff --git a/src/main/java/com/google/devtools/build/lib/profiler/statistics/PhaseVfsStatistics.java b/src/main/java/com/google/devtools/build/lib/profiler/statistics/PhaseVfsStatistics.java new file mode 100644 index 0000000000..e75359bf82 --- /dev/null +++ b/src/main/java/com/google/devtools/build/lib/profiler/statistics/PhaseVfsStatistics.java @@ -0,0 +1,138 @@ +// 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.statistics; + +import com.google.common.collect.Maps; +import com.google.common.collect.Multimaps; +import com.google.common.collect.Ordering; +import com.google.common.collect.TreeMultimap; +import com.google.devtools.build.lib.profiler.ProfileInfo; +import com.google.devtools.build.lib.profiler.ProfileInfo.Task; +import com.google.devtools.build.lib.profiler.ProfilePhase; +import com.google.devtools.build.lib.profiler.ProfilerTask; + +import java.util.Arrays; +import java.util.EnumMap; +import java.util.HashMap; +import java.util.Iterator; +import java.util.List; +import java.util.Map; +import java.util.Map.Entry; + +/** + * Compute and store statistics of all {@link ProfilerTask}s that begin with VFS_ in sorted order. + */ +public final class PhaseVfsStatistics implements Iterable { + + /** + * Pair of duration and count for sorting by duration first and count in case of tie + */ + public static class Stat implements Comparable { + public long duration; + public long count; + + @Override + public int compareTo(Stat o) { + return this.duration == o.duration + ? Long.compare(this.count, o.count) + : Long.compare(this.duration, o.duration); + } + } + + private final ProfilePhase phase; + private final EnumMap> sortedStatistics; + private final String workSpaceName; + + public PhaseVfsStatistics(final String workSpaceName, ProfilePhase phase, ProfileInfo info) { + this.workSpaceName = workSpaceName; + this.phase = phase; + this.sortedStatistics = Maps.newEnumMap(ProfilerTask.class); + + Task phaseTask = info.getPhaseTask(phase); + if (phaseTask == null) { + return; + } + collectVfsEntries(info.getTasksForPhase(phaseTask)); + } + + public ProfilePhase getProfilePhase() { + return phase; + } + + public boolean isEmpty() { + return sortedStatistics.isEmpty(); + } + + public Iterable> getSortedStatistics(ProfilerTask taskType) { + return sortedStatistics.get(taskType).entries(); + } + + public int getStatisticsCount(ProfilerTask taskType) { + return sortedStatistics.get(taskType).size(); + } + + @Override + public Iterator iterator() { + return sortedStatistics.keySet().iterator(); + } + + /** + * Group into VFS operations and build maps from path to duration. + */ + private void collectVfsEntries(List taskList) { + EnumMap> stats = Maps.newEnumMap(ProfilerTask.class); + for (Task task : taskList) { + collectVfsEntries(Arrays.asList(task.subtasks)); + if (!task.type.name().startsWith("VFS_")) { + continue; + } + + Map statsForType = stats.get(task.type); + if (statsForType == null) { + statsForType = new HashMap<>(); + stats.put(task.type, statsForType); + } + + String path = currentPathMapping(task.getDescription()); + + Stat stat = statsForType.get(path); + if (stat == null) { + stat = new Stat(); + } + + stat.duration += task.duration; + stat.count++; + statsForType.put(path, stat); + } + // Reverse the maps to get maps from duration to path. We use a TreeMultimap to sort by + // duration and because durations are not unique. + for (ProfilerTask type : stats.keySet()) { + Map statsForType = stats.get(type); + TreeMultimap sortedStats = + TreeMultimap.create(Ordering.natural().reverse(), Ordering.natural()); + + Multimaps.invertFrom(Multimaps.forMap(statsForType), sortedStats); + sortedStatistics.put(type, sortedStats); + } + } + + private String currentPathMapping(String input) { + if (workSpaceName.isEmpty()) { + return input; + } else { + return input.substring(input.lastIndexOf("/" + workSpaceName) + 1); + } + } +} + diff --git a/src/main/java/com/google/devtools/build/lib/profiler/statistics/SkylarkStatistics.java b/src/main/java/com/google/devtools/build/lib/profiler/statistics/SkylarkStatistics.java new file mode 100644 index 0000000000..014391976e --- /dev/null +++ b/src/main/java/com/google/devtools/build/lib/profiler/statistics/SkylarkStatistics.java @@ -0,0 +1,113 @@ +// 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.statistics; + +import com.google.common.collect.ListMultimap; +import com.google.common.collect.Multimaps; +import com.google.devtools.build.lib.profiler.ProfileInfo; +import com.google.devtools.build.lib.profiler.ProfileInfo.Task; + +import java.io.PrintStream; +import java.util.ArrayList; +import java.util.List; +import java.util.Map.Entry; + +/** + * Computes various statistics for Skylark and built-in function usage and prints it to a given + * {@link PrintStream}. + */ +public final class SkylarkStatistics { + + private final ListMultimap userFunctionTasks; + private final ListMultimap builtinFunctionTasks; + private final List userFunctionStats; + private final List builtinFunctionStats; + private long userTotalNanos; + private long builtinTotalNanos; + + public SkylarkStatistics(ProfileInfo info) { + userFunctionTasks = info.getSkylarkUserFunctionTasks(); + builtinFunctionTasks = info.getSkylarkBuiltinFunctionTasks(); + userFunctionStats = new ArrayList<>(); + builtinFunctionStats = new ArrayList<>(); + computeStatistics(); + } + + /** + * @return the total time taken by all calls to built-in Skylark functions + */ + public long getBuiltinTotalNanos() { + return builtinTotalNanos; + } + + /** + * @return the total time taken by all calls to user-defined Skylark functions + */ + public long getUserTotalNanos() { + return userTotalNanos; + } + + /** + * @return a map from user-defined function descriptions of the form file:line#function to all + * corresponding {@link com.google.devtools.build.lib.profiler.ProfileInfo.Task}s. + */ + public ListMultimap getUserFunctionTasks() { + return userFunctionTasks; + } + + /** + * @return a map from built-in function descriptions of the form package.class#method to all + * corresponding {@link com.google.devtools.build.lib.profiler.ProfileInfo.Task}s. + */ + public ListMultimap getBuiltinFunctionTasks() { + return builtinFunctionTasks; + } + + public List getBuiltinFunctionStats() { + return builtinFunctionStats; + } + + public List getUserFunctionStats() { + return userFunctionStats; + } + + /** + * For each Skylark function compute a {@link TasksStatistics} object from the execution times of + * all corresponding {@link Task}s from either {@link #userFunctionTasks} or + * {@link #builtinFunctionTasks}. Fills fields {@link #userFunctionStats} and + * {@link #builtinFunctionStats}. + */ + private void computeStatistics() { + userTotalNanos = computeStatistics(userFunctionTasks, userFunctionStats); + builtinTotalNanos = computeStatistics(builtinFunctionTasks, builtinFunctionStats); + } + + /** + * For each Skylark function compute a {@link TasksStatistics} object from the execution times of + * all corresponding {@link Task}s and add it to the list. + * @param tasks Map from function name to all corresponding tasks. + * @param stats The list to which {@link TasksStatistics} are to be added. + * @return The sum of the execution times of all {@link Task} values in the map. + */ + private static long computeStatistics( + ListMultimap tasks, List stats) { + long total = 0L; + for (Entry> entry : Multimaps.asMap(tasks).entrySet()) { + TasksStatistics functionStats = TasksStatistics.create(entry.getKey(), entry.getValue()); + stats.add(functionStats); + total += functionStats.totalNanos; + } + return total; + } +} diff --git a/src/main/java/com/google/devtools/build/lib/profiler/statistics/TasksStatistics.java b/src/main/java/com/google/devtools/build/lib/profiler/statistics/TasksStatistics.java new file mode 100644 index 0000000000..0e7ea71bf0 --- /dev/null +++ b/src/main/java/com/google/devtools/build/lib/profiler/statistics/TasksStatistics.java @@ -0,0 +1,142 @@ +// 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.statistics; + +import com.google.devtools.build.lib.profiler.ProfileInfo.Task; + +import java.util.Collections; +import java.util.Comparator; +import java.util.List; + +/** + * Data container to aggregate execution time statistics of multiple tasks grouped by some name. + */ +public class TasksStatistics { + public final String name; + public final int count; + public final long minNanos; + public final long maxNanos; + public final double medianNanos; + /** Standard deviation of the execution time in milliseconds since computation in nanoseconds can + * overflow. + */ + public final double standardDeviationMillis; + public final long totalNanos; + public final long selfNanos; + + public TasksStatistics( + String name, + int count, + long minNanos, + long maxNanos, + double medianNanos, + double standardDeviationMillis, + long totalNanos, + long selfNanos) { + this.name = name; + this.count = count; + this.minNanos = minNanos; + this.maxNanos = maxNanos; + this.medianNanos = medianNanos; + this.standardDeviationMillis = standardDeviationMillis; + this.totalNanos = totalNanos; + this.selfNanos = selfNanos; + } + + public double minimumMillis() { + return toMilliSeconds(minNanos); + } + + public double maximumMillis() { + return toMilliSeconds(maxNanos); + } + + public double meanNanos() { + return totalNanos / count; + } + + public double meanMillis() { + return toMilliSeconds(meanNanos()); + } + + public double medianMillis() { + return toMilliSeconds(medianNanos); + } + + public double totalMillis() { + return toMilliSeconds(totalNanos); + } + + public double selfMillis() { + return toMilliSeconds(selfNanos); + } + + public double selfMeanNanos() { + return selfNanos / count; + } + + public double selfMeanMillis() { + return toMilliSeconds(selfMeanNanos()); + } + + /** + * @param name + * @param tasks + * @return The set of statistics grouped in this class, computed from a list of {@link Task}s. + */ + public static TasksStatistics create(String name, List tasks) { + Collections.sort( + tasks, + new Comparator() { + @Override + public int compare(Task o1, Task o2) { + return Long.compare(o1.duration, o2.duration); + } + }); + int count = tasks.size(); + long min = tasks.get(0).duration; + long max = tasks.get(count - 1).duration; + + int midIndex = count / 2; + double median = + tasks.size() % 2 == 0 + ? (tasks.get(midIndex).duration + tasks.get(midIndex - 1).duration) / 2.0 + : tasks.get(midIndex).duration; + + // Compute standard deviation with a shift to avoid catastrophic cancellation + // and also do it in milliseconds, as in nanoseconds it overflows + long sum = 0L; + long self = 0L; + double sumOfSquaredShiftedMillis = 0L; + final long shift = min; + + for (Task task : tasks) { + sum += task.duration; + self += task.duration - task.getInheritedDuration(); + double taskDurationShiftMillis = toMilliSeconds(task.duration - shift); + sumOfSquaredShiftedMillis += taskDurationShiftMillis * taskDurationShiftMillis; + } + double sumShiftedMillis = toMilliSeconds(sum - count * shift); + + double standardDeviation = + Math.sqrt( + (sumOfSquaredShiftedMillis - (sumShiftedMillis * sumShiftedMillis) / count) / count); + + return new TasksStatistics(name, count, min, max, median, standardDeviation, sum, self); + } + + static double toMilliSeconds(double nanoseconds) { + return nanoseconds / 1000000.0; + } +} diff --git a/src/main/java/com/google/devtools/build/lib/runtime/commands/ProfileCommand.java b/src/main/java/com/google/devtools/build/lib/runtime/commands/ProfileCommand.java index e7ebdbe557..8e28f5652c 100644 --- a/src/main/java/com/google/devtools/build/lib/runtime/commands/ProfileCommand.java +++ b/src/main/java/com/google/devtools/build/lib/runtime/commands/ProfileCommand.java @@ -13,23 +13,17 @@ // limitations under the License. package com.google.devtools.build.lib.runtime.commands; -import com.google.common.base.Function; -import com.google.common.base.Functions; -import com.google.common.base.Preconditions; -import com.google.common.collect.Maps; -import com.google.common.collect.Multimaps; -import com.google.common.collect.Ordering; -import com.google.common.collect.TreeMultimap; -import com.google.devtools.build.lib.actions.MiddlemanAction; import com.google.devtools.build.lib.events.Event; import com.google.devtools.build.lib.events.EventHandler; import com.google.devtools.build.lib.profiler.ProfileInfo; -import com.google.devtools.build.lib.profiler.ProfileInfo.CriticalPathEntry; import com.google.devtools.build.lib.profiler.ProfileInfo.InfoListener; import com.google.devtools.build.lib.profiler.ProfilePhase; -import com.google.devtools.build.lib.profiler.ProfilePhaseStatistics; import com.google.devtools.build.lib.profiler.ProfilerTask; -import com.google.devtools.build.lib.profiler.chart.HtmlCreator; +import com.google.devtools.build.lib.profiler.output.HtmlCreator; +import com.google.devtools.build.lib.profiler.output.PhaseText; +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.runtime.BlazeCommand; import com.google.devtools.build.lib.runtime.BlazeRuntime; import com.google.devtools.build.lib.runtime.Command; @@ -44,17 +38,9 @@ import com.google.devtools.common.options.OptionsBase; import com.google.devtools.common.options.OptionsParser; import com.google.devtools.common.options.OptionsProvider; -import java.io.ByteArrayOutputStream; import java.io.IOException; import java.io.PrintStream; -import java.io.UnsupportedEncodingException; -import java.util.ArrayList; -import java.util.Arrays; -import java.util.Collections; import java.util.EnumMap; -import java.util.EnumSet; -import java.util.List; -import java.util.Map; /** * Command line wrapper for analyzing Blaze build profiles. @@ -68,9 +54,6 @@ import java.util.Map; mustRunInWorkspace = false) public final class ProfileCommand implements BlazeCommand { - private final String TWO_COLUMN_FORMAT = "%-37s %10s\n"; - private final String THREE_COLUMN_FORMAT = "%-28s %10s %8s\n"; - public static class DumpConverter extends Converters.StringSetConverter { public DumpConverter() { super("text", "raw", "text-unsorted", "raw-unsorted"); @@ -120,8 +103,6 @@ public final class ProfileCommand implements BlazeCommand { public int vfsStatsLimit; } - private Function currentPathMapping = Functions.identity(); - private InfoListener getInfoListener(final CommandEnvironment env) { return new InfoListener() { private final EventHandler reporter = env.getReporter(); @@ -151,17 +132,6 @@ public final class ProfileCommand implements BlazeCommand { opts.vfsStatsLimit = 0; } - currentPathMapping = new Function() { - @Override - public String apply(String input) { - if (runtime.getWorkspaceName().isEmpty()) { - return input; - } else { - return input.substring(input.lastIndexOf("/" + runtime.getWorkspaceName()) + 1); - } - } - }; - PrintStream out = new PrintStream(env.getReporter().getOutErr().getOutputStream()); try { env.getReporter().handle(Event.warn( @@ -173,6 +143,16 @@ public final class ProfileCommand implements BlazeCommand { try { ProfileInfo info = ProfileInfo.loadProfileVerbosely( profileFile, getInfoListener(env)); + ProfileInfo.aggregateProfile(info, getInfoListener(env)); + + PhaseSummaryStatistics phaseSummaryStatistics = new PhaseSummaryStatistics(info); + EnumMap phaseStatistics = + new EnumMap<>(ProfilePhase.class); + for (ProfilePhase phase : ProfilePhase.values()) { + phaseStatistics.put( + phase, new PhaseStatistics(phase, info, runtime.getWorkspaceName())); + } + if (opts.dumpMode != null) { dumpProfile(env, info, out, opts.dumpMode); } else if (opts.html) { @@ -181,14 +161,24 @@ public final class ProfileCommand implements BlazeCommand { env.getReporter().handle(Event.info("Creating HTML output in " + htmlFile)); - HtmlCreator.createHtml( + HtmlCreator.create( info, htmlFile, - getStatistics(env, info, opts), + phaseSummaryStatistics, + phaseStatistics, opts.htmlDetails, - opts.htmlPixelsPerSecond); + opts.htmlPixelsPerSecond, + opts.vfsStatsLimit); } else { - createText(env, info, out, opts); + CriticalPathStatistics critPathStats = new CriticalPathStatistics(info); + new PhaseText( + out, + phaseSummaryStatistics, + phaseStatistics, + critPathStats, + info.getMissingActionsCount(), + opts.vfsStatsLimit) + .print(); } } catch (IOException e) { env.getReporter().handle(Event.error( @@ -201,70 +191,6 @@ public final class ProfileCommand implements BlazeCommand { return ExitCode.SUCCESS; } - private void createText(CommandEnvironment env, ProfileInfo info, PrintStream out, - ProfileOptions opts) { - List statistics = getStatistics(env, info, opts); - - for (ProfilePhaseStatistics stat : statistics) { - String title = stat.getTitle(); - - if (!title.isEmpty()) { - out.println("\n=== " + title.toUpperCase() + " ===\n"); - } - out.print(stat.getStatistics()); - } - } - - private List getStatistics( - CommandEnvironment env, ProfileInfo info, ProfileOptions opts) { - try { - ProfileInfo.aggregateProfile(info, getInfoListener(env)); - env.getReporter().handle(Event.info("Analyzing relationships")); - - info.analyzeRelationships(); - - List statistics = new ArrayList<>(); - - // Print phase durations and total execution time - ByteArrayOutputStream byteOutput = new ByteArrayOutputStream(); - PrintStream out = new PrintStream(byteOutput, false, "UTF-8"); - long duration = 0; - for (ProfilePhase phase : ProfilePhase.values()) { - ProfileInfo.Task phaseTask = info.getPhaseTask(phase); - if (phaseTask != null) { - duration += info.getPhaseDuration(phaseTask); - } - } - for (ProfilePhase phase : ProfilePhase.values()) { - ProfileInfo.Task phaseTask = info.getPhaseTask(phase); - if (phaseTask != null) { - long phaseDuration = info.getPhaseDuration(phaseTask); - out.printf(THREE_COLUMN_FORMAT, "Total " + phase.nick + " phase time", - TimeUtilities.prettyTime(phaseDuration), prettyPercentage(phaseDuration, duration)); - } - } - out.printf(THREE_COLUMN_FORMAT, "Total run time", TimeUtilities.prettyTime(duration), - "100.00%"); - statistics.add(new ProfilePhaseStatistics("Phase Summary Information", - new String(byteOutput.toByteArray(), "UTF-8"))); - - // Print details of major phases - if (duration > 0) { - statistics.add(formatInitPhaseStatistics(info, opts)); - statistics.add(formatLoadingPhaseStatistics(info, opts)); - statistics.add(formatAnalysisPhaseStatistics(info, opts)); - ProfilePhaseStatistics stat = formatExecutionPhaseStatistics(info, opts); - if (stat != null) { - statistics.add(stat); - } - } - - return statistics; - } catch (UnsupportedEncodingException e) { - throw new AssertionError("Should not happen since, UTF8 is available on all JVMs"); - } - } - private void dumpProfile( CommandEnvironment env, ProfileInfo info, PrintStream out, String dumpMode) { if (!dumpMode.contains("unsorted")) { @@ -324,428 +250,4 @@ public final class ProfileCommand implements BlazeCommand { + aggregateString.toString().trim() + "|" + task.type + "|" + task.getDescription()); } - - /** - * Converts relative duration to the percentage string - * @return formatted percentage string or "N/A" if result is undefined. - */ - private static String prettyPercentage(long duration, long total) { - if (total == 0) { - // Return "not available" string if total is 0 and result is undefined. - return "N/A"; - } - return String.format("%5.2f%%", duration*100.0/total); - } - - private void printCriticalPath(String title, PrintStream out, CriticalPathEntry path) { - out.printf("\n%s (%s):%n", title, TimeUtilities.prettyTime(path.cumulativeDuration)); - - boolean lightCriticalPath = isLightCriticalPath(path); - out.println(lightCriticalPath ? - String.format("%6s %11s %8s %s", "Id", "Time", "Percentage", "Description") - : String.format("%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 (lightCriticalPath) { - out.printf("%6d %11s %8s %s%n", path.task.id, TimeUtilities.prettyTime(path.duration), - prettyPercentage(path.duration, totalPathTime), desc); - } else { - out.printf("%6d %11s %8s %8s %s%n", path.task.id, - TimeUtilities.prettyTime(path.duration), - prettyPercentage(path.duration, totalPathTime), - prettyPercentage(path.getCriticalTime(), totalPathTime), desc); - } - } - } - if (middlemanCount > 0) { - if (lightCriticalPath) { - out.printf(" %11s %8s [%d middleman actions]%n", - TimeUtilities.prettyTime(middlemanDuration), - prettyPercentage(middlemanDuration, totalPathTime), middlemanCount); - } else { - out.printf(" %11s %8s %8s [%d middleman actions]%n", - TimeUtilities.prettyTime(middlemanDuration), - prettyPercentage(middlemanDuration, totalPathTime), - prettyPercentage(middlemanCritTime, totalPathTime), middlemanCount); - } - } - } - - private boolean isLightCriticalPath(CriticalPathEntry path) { - return path.task.type == ProfilerTask.CRITICAL_PATH_COMPONENT; - } - - private void printShortPhaseAnalysis(ProfileInfo info, PrintStream out, ProfilePhase phase) { - ProfileInfo.Task phaseTask = info.getPhaseTask(phase); - if (phaseTask != null) { - long phaseDuration = info.getPhaseDuration(phaseTask); - out.printf(TWO_COLUMN_FORMAT, "Total " + phase.nick + " phase time", - TimeUtilities.prettyTime(phaseDuration)); - printTimeDistributionByType(info, out, phaseTask); - } - } - - private void printTimeDistributionByType(ProfileInfo info, PrintStream out, - ProfileInfo.Task phaseTask) { - List taskList = info.getTasksForPhase(phaseTask); - long phaseDuration = info.getPhaseDuration(phaseTask); - long totalDuration = phaseDuration; - for (ProfileInfo.Task task : taskList) { - // Tasks on the phaseTask thread already accounted for in the phaseDuration. - if (task.threadId != phaseTask.threadId) { - totalDuration += task.duration; - } - } - boolean headerNeeded = true; - for (ProfilerTask type : ProfilerTask.values()) { - ProfileInfo.AggregateAttr stats = info.getStatsForType(type, taskList); - if (stats.count > 0 && stats.totalTime > 0) { - if (headerNeeded) { - out.println("\nTotal time (across all threads) spent on:"); - out.printf("%18s %8s %8s %11s%n", "Type", "Total", "Count", "Average"); - headerNeeded = false; - } - out.printf("%18s %8s %8d %11s%n", type.toString(), - prettyPercentage(stats.totalTime, totalDuration), stats.count, - TimeUtilities.prettyTime(stats.totalTime / stats.count)); - } - } - } - - static class Stat implements Comparable { - public long duration; - public long frequency; - - @Override - public int compareTo(Stat o) { - return this.duration == o.duration ? Long.compare(this.frequency, o.frequency) - : Long.compare(this.duration, o.duration); - } - } - - /** - * 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. - * - * @param info profiling data. - * @param out output stream. - * @param phase build phase. - * @param limit maximum number of statistics to print, or -1 for no limit. - */ - private void printVfsStatistics(ProfileInfo info, PrintStream out, - ProfilePhase phase, int limit) { - ProfileInfo.Task phaseTask = info.getPhaseTask(phase); - if (phaseTask == null) { - return; - } - - if (limit == 0) { - return; - } - - // Group into VFS operations and build maps from path to duration. - - List taskList = info.getTasksForPhase(phaseTask); - EnumMap> stats = Maps.newEnumMap(ProfilerTask.class); - - collectVfsEntries(stats, taskList); - - if (!stats.isEmpty()) { - out.printf("\nVFS path statistics:\n"); - out.printf("%15s %10s %10s %s\n", "Type", "Frequency", "Duration", "Path"); - } - - // Reverse the maps to get maps from duration to path. We use a TreeMultimap to sort by duration - // and because durations are not unique. - - for (ProfilerTask type : stats.keySet()) { - Map statsForType = stats.get(type); - TreeMultimap sortedStats = - TreeMultimap.create(Ordering.natural().reverse(), Ordering.natural()); - - Multimaps.invertFrom(Multimaps.forMap(statsForType), sortedStats); - - int numPrinted = 0; - for (Map.Entry stat : sortedStats.entries()) { - if (limit != -1 && numPrinted++ == limit) { - out.printf("... %d more ...\n", sortedStats.size() - limit); - break; - } - out.printf("%15s %10d %10s %s\n", - type.name(), stat.getKey().frequency, TimeUtilities.prettyTime(stat.getKey().duration), - stat.getValue()); - } - } - } - - private void collectVfsEntries(EnumMap> stats, - List taskList) { - for (ProfileInfo.Task task : taskList) { - collectVfsEntries(stats, Arrays.asList(task.subtasks)); - if (!task.type.name().startsWith("VFS_")) { - continue; - } - - Map statsForType = stats.get(task.type); - if (statsForType == null) { - statsForType = Maps.newHashMap(); - stats.put(task.type, statsForType); - } - - String path = currentPathMapping.apply(task.getDescription()); - - Stat stat = statsForType.get(path); - if (stat == null) { - stat = new Stat(); - } - - stat.duration += task.duration; - stat.frequency++; - statsForType.put(path, stat); - } - } - - /** - * Returns set of profiler tasks to be filtered from critical path. - * Also always filters out ACTION_LOCK and WAIT tasks to simulate - * unlimited resource critical path (see comments inside formatExecutionPhaseStatistics() - * method). - */ - private EnumSet getTypeFilter(ProfilerTask... tasks) { - EnumSet filter = EnumSet.of(ProfilerTask.ACTION_LOCK, ProfilerTask.WAIT); - Collections.addAll(filter, tasks); - return filter; - } - - private ProfilePhaseStatistics formatInitPhaseStatistics(ProfileInfo info, ProfileOptions opts) - throws UnsupportedEncodingException { - return formatSimplePhaseStatistics(info, opts, "Init", ProfilePhase.INIT); - } - - private ProfilePhaseStatistics formatLoadingPhaseStatistics(ProfileInfo info, ProfileOptions opts) - throws UnsupportedEncodingException { - return formatSimplePhaseStatistics(info, opts, "Loading", ProfilePhase.LOAD); - } - - private ProfilePhaseStatistics formatAnalysisPhaseStatistics(ProfileInfo info, - ProfileOptions opts) - throws UnsupportedEncodingException { - return formatSimplePhaseStatistics(info, opts, "Analysis", ProfilePhase.ANALYZE); - } - - private ProfilePhaseStatistics formatSimplePhaseStatistics(ProfileInfo info, - ProfileOptions opts, - String name, - ProfilePhase phase) - throws UnsupportedEncodingException { - ByteArrayOutputStream byteOutput = new ByteArrayOutputStream(); - PrintStream out = new PrintStream(byteOutput, false, "UTF-8"); - - printShortPhaseAnalysis(info, out, phase); - printVfsStatistics(info, out, phase, opts.vfsStatsLimit); - return new ProfilePhaseStatistics(name + " Phase Information", - new String(byteOutput.toByteArray(), "UTF-8")); - } - - private ProfilePhaseStatistics formatExecutionPhaseStatistics(ProfileInfo info, - ProfileOptions opts) - throws UnsupportedEncodingException { - ByteArrayOutputStream byteOutput = new ByteArrayOutputStream(); - PrintStream out = new PrintStream(byteOutput, false, "UTF-8"); - - ProfileInfo.Task prepPhase = info.getPhaseTask(ProfilePhase.PREPARE); - ProfileInfo.Task execPhase = info.getPhaseTask(ProfilePhase.EXECUTE); - ProfileInfo.Task finishPhase = info.getPhaseTask(ProfilePhase.FINISH); - if (execPhase == null) { - return null; - } - - List execTasks = info.getTasksForPhase(execPhase); - long graphTime = info.getStatsForType(ProfilerTask.ACTION_GRAPH, execTasks).totalTime; - long execTime = info.getPhaseDuration(execPhase) - graphTime; - - if (prepPhase != null) { - out.printf(TWO_COLUMN_FORMAT, "Total preparation time", - TimeUtilities.prettyTime(info.getPhaseDuration(prepPhase))); - } - out.printf(TWO_COLUMN_FORMAT, "Total execution phase time", - TimeUtilities.prettyTime(info.getPhaseDuration(execPhase))); - if (finishPhase != null) { - out.printf(TWO_COLUMN_FORMAT, "Total time finalizing build", - TimeUtilities.prettyTime(info.getPhaseDuration(finishPhase))); - } - out.println(); - out.printf(TWO_COLUMN_FORMAT, "Action dependency map creation", - TimeUtilities.prettyTime(graphTime)); - out.printf(TWO_COLUMN_FORMAT, "Actual execution time", - TimeUtilities.prettyTime(execTime)); - - EnumSet typeFilter = EnumSet.noneOf(ProfilerTask.class); - CriticalPathEntry totalPath = info.getCriticalPath(typeFilter); - info.analyzeCriticalPath(typeFilter, totalPath); - - typeFilter = getTypeFilter(); - CriticalPathEntry optimalPath = info.getCriticalPath(typeFilter); - info.analyzeCriticalPath(typeFilter, optimalPath); - - if (totalPath != null) { - printCriticalPathTimingBreakdown(info, totalPath, optimalPath, execTime, out); - } else { - out.println("\nCritical path not available because no action graph was generated."); - } - - printTimeDistributionByType(info, out, execPhase); - - if (totalPath != null) { - printCriticalPath("Critical path", out, totalPath); - // In light critical path we do not record scheduling delay data so it does not make sense - // to differentiate it. - if (!isLightCriticalPath(totalPath)) { - printCriticalPath("Critical path excluding scheduling delays", out, optimalPath); - } - } - - if (info.getMissingActionsCount() > 0) { - out.println("\n" + info.getMissingActionsCount() + " action(s) are present in the" - + " action graph but missing instrumentation data. Most likely profile file" - + " has been created for the failed or aborted build."); - } - - printVfsStatistics(info, out, ProfilePhase.EXECUTE, opts.vfsStatsLimit); - - return new ProfilePhaseStatistics("Execution Phase Information", - new String(byteOutput.toByteArray(), "UTF-8")); - } - - void printCriticalPathTimingBreakdown(ProfileInfo info, CriticalPathEntry totalPath, - CriticalPathEntry optimalPath, long execTime, PrintStream out) { - Preconditions.checkNotNull(totalPath); - Preconditions.checkNotNull(optimalPath); - // TODO(bazel-team): Print remote vs build stats recorded by CriticalPathStats - if (isLightCriticalPath(totalPath)) { - return; - } - out.println(totalPath.task.type); - // Worker thread pool scheduling delays for the actual critical path. - long workerWaitTime = 0; - long mainThreadWaitTime = 0; - for (ProfileInfo.CriticalPathEntry entry = totalPath; entry != null; entry = entry.next) { - workerWaitTime += info.getActionWaitTime(entry.task); - mainThreadWaitTime += info.getActionQueueTime(entry.task); - } - out.printf(TWO_COLUMN_FORMAT, "Worker thread scheduling delays", - TimeUtilities.prettyTime(workerWaitTime)); - out.printf(TWO_COLUMN_FORMAT, "Main thread scheduling delays", - TimeUtilities.prettyTime(mainThreadWaitTime)); - - out.println("\nCritical path time:"); - // Actual critical path. - long totalTime = totalPath.cumulativeDuration; - out.printf("%-37s %10s (%s of execution time)\n", "Actual time", - TimeUtilities.prettyTime(totalTime), - prettyPercentage(totalTime, execTime)); - // Unlimited resource critical path. Essentially, we assume that if we - // remove all scheduling delays caused by resource semaphore contention, - // each action execution time would not change (even though load now would - // be substantially higher - so this assumption might be incorrect but it is - // still useful for modeling). Given those assumptions we calculate critical - // path excluding scheduling delays. - long optimalTime = optimalPath.cumulativeDuration; - out.printf("%-37s %10s (%s of execution time)\n", "Time excluding scheduling delays", - TimeUtilities.prettyTime(optimalTime), - prettyPercentage(optimalTime, execTime)); - - // Artificial critical path if we ignore all the time spent in all tasks, - // except time directly attributed to the ACTION tasks. - out.println("\nTime related to:"); - - EnumSet typeFilter = EnumSet.allOf(ProfilerTask.class); - ProfileInfo.CriticalPathEntry path = info.getCriticalPath(typeFilter); - out.printf(TWO_COLUMN_FORMAT, "the builder overhead", - prettyPercentage(path.cumulativeDuration, totalTime)); - - typeFilter = getTypeFilter(); - for (ProfilerTask task : ProfilerTask.values()) { - if (task.name().startsWith("VFS_")) { - typeFilter.add(task); - } - } - path = info.getCriticalPath(typeFilter); - out.printf(TWO_COLUMN_FORMAT, "the VFS calls", - prettyPercentage(optimalTime - path.cumulativeDuration, optimalTime)); - - typeFilter = getTypeFilter(ProfilerTask.ACTION_CHECK); - path = info.getCriticalPath(typeFilter); - out.printf(TWO_COLUMN_FORMAT, "the dependency checking", - prettyPercentage(optimalTime - path.cumulativeDuration, optimalTime)); - - typeFilter = getTypeFilter(ProfilerTask.ACTION_EXECUTE); - path = info.getCriticalPath(typeFilter); - out.printf(TWO_COLUMN_FORMAT, "the execution setup", - prettyPercentage(optimalTime - path.cumulativeDuration, optimalTime)); - - typeFilter = getTypeFilter(ProfilerTask.SPAWN, ProfilerTask.LOCAL_EXECUTION); - path = info.getCriticalPath(typeFilter); - out.printf(TWO_COLUMN_FORMAT, "local execution", - prettyPercentage(optimalTime - path.cumulativeDuration, optimalTime)); - - typeFilter = getTypeFilter(ProfilerTask.SCANNER); - path = info.getCriticalPath(typeFilter); - out.printf(TWO_COLUMN_FORMAT, "the include scanner", - prettyPercentage(optimalTime - path.cumulativeDuration, optimalTime)); - - typeFilter = getTypeFilter(ProfilerTask.REMOTE_EXECUTION, ProfilerTask.PROCESS_TIME, - ProfilerTask.LOCAL_PARSE, ProfilerTask.UPLOAD_TIME, - ProfilerTask.REMOTE_QUEUE, ProfilerTask.REMOTE_SETUP, ProfilerTask.FETCH); - path = info.getCriticalPath(typeFilter); - out.printf(TWO_COLUMN_FORMAT, "Remote execution (cumulative)", - prettyPercentage(optimalTime - path.cumulativeDuration, optimalTime)); - - typeFilter = getTypeFilter( ProfilerTask.UPLOAD_TIME, ProfilerTask.REMOTE_SETUP); - path = info.getCriticalPath(typeFilter); - out.printf(TWO_COLUMN_FORMAT, " file uploads", - prettyPercentage(optimalTime - path.cumulativeDuration, optimalTime)); - - typeFilter = getTypeFilter(ProfilerTask.FETCH); - path = info.getCriticalPath(typeFilter); - out.printf(TWO_COLUMN_FORMAT, " file fetching", - prettyPercentage(optimalTime - path.cumulativeDuration, optimalTime)); - - typeFilter = getTypeFilter(ProfilerTask.PROCESS_TIME); - path = info.getCriticalPath(typeFilter); - out.printf(TWO_COLUMN_FORMAT, " process time", - prettyPercentage(optimalTime - path.cumulativeDuration, optimalTime)); - - typeFilter = getTypeFilter(ProfilerTask.REMOTE_QUEUE); - path = info.getCriticalPath(typeFilter); - out.printf(TWO_COLUMN_FORMAT, " remote queueing", - prettyPercentage(optimalTime - path.cumulativeDuration, optimalTime)); - - typeFilter = getTypeFilter(ProfilerTask.LOCAL_PARSE); - path = info.getCriticalPath(typeFilter); - out.printf(TWO_COLUMN_FORMAT, " remote execution parse", - prettyPercentage(optimalTime - path.cumulativeDuration, optimalTime)); - - typeFilter = getTypeFilter(ProfilerTask.REMOTE_EXECUTION); - path = info.getCriticalPath(typeFilter); - out.printf(TWO_COLUMN_FORMAT, " other remote activities", - prettyPercentage(optimalTime - path.cumulativeDuration, optimalTime)); - } } diff --git a/src/main/java/com/google/devtools/build/lib/sandbox/BUILD b/src/main/java/com/google/devtools/build/lib/sandbox/BUILD index 53b707f6b6..d472c910f1 100644 --- a/src/main/java/com/google/devtools/build/lib/sandbox/BUILD +++ b/src/main/java/com/google/devtools/build/lib/sandbox/BUILD @@ -13,10 +13,13 @@ java_library( "//src/main/java:buildtool-runtime", "//src/main/java:common", "//src/main/java:events", + "//src/main/java:io", "//src/main/java:options", + "//src/main/java:os_util", "//src/main/java:packages", "//src/main/java:shell", "//src/main/java:unix", + "//src/main/java:util", "//src/main/java:vfs", "//src/main/java/com/google/devtools/build/lib/standalone", "//third_party:guava", diff --git a/src/main/java/com/google/devtools/build/lib/standalone/BUILD b/src/main/java/com/google/devtools/build/lib/standalone/BUILD index 3653e06958..a9e819467c 100644 --- a/src/main/java/com/google/devtools/build/lib/standalone/BUILD +++ b/src/main/java/com/google/devtools/build/lib/standalone/BUILD @@ -12,8 +12,11 @@ java_library( "//src/main/java:analysis-exec-rules-skyframe", "//src/main/java:buildtool-runtime", "//src/main/java:common", + "//src/main/java:io", + "//src/main/java:os_util", "//src/main/java:packages", "//src/main/java:shell", + "//src/main/java:util", "//src/main/java:vfs", "//third_party:guava", ], diff --git a/src/main/java/com/google/devtools/build/lib/util/TimeUtilities.java b/src/main/java/com/google/devtools/build/lib/util/TimeUtilities.java index 689744a36f..683a0ba798 100644 --- a/src/main/java/com/google/devtools/build/lib/util/TimeUtilities.java +++ b/src/main/java/com/google/devtools/build/lib/util/TimeUtilities.java @@ -27,7 +27,7 @@ public class TimeUtilities { * * @param timeInNs The length of time in nanoseconds. */ - public static String prettyTime(long timeInNs) { + public static String prettyTime(double timeInNs) { double ms = timeInNs / 1000000.0; if (ms < 10.0) { return String.format("%.2f ms", ms); diff --git a/src/main/java/com/google/devtools/build/lib/worker/BUILD b/src/main/java/com/google/devtools/build/lib/worker/BUILD index 4d6cb1a4e5..08154b9bb5 100644 --- a/src/main/java/com/google/devtools/build/lib/worker/BUILD +++ b/src/main/java/com/google/devtools/build/lib/worker/BUILD @@ -14,8 +14,10 @@ java_library( "//src/main/java:common", "//src/main/java:concurrent", "//src/main/java:events", + "//src/main/java:io", "//src/main/java:options", "//src/main/java:packages", + "//src/main/java:util", "//src/main/java:vfs", "//src/main/java/com/google/devtools/build/lib/standalone", "//src/main/protobuf:proto_worker_protocol", -- cgit v1.2.3