diff options
author | Klaas Boesche <klaasb@google.com> | 2015-09-22 11:29:47 +0000 |
---|---|---|
committer | Laszlo Csomor <laszlocsomor@google.com> | 2015-09-22 17:07:41 +0000 |
commit | 6bd4f2da3288a1508bdafe3072a1a2f611eb8316 (patch) | |
tree | f4750c67b63d84dc841d8436d899af9f3da08bb7 | |
parent | 907d5795724641408f1aad21a02ab8adfd6e9c76 (diff) |
Heavily refactor ProfileCommand to separate output and statistics generation and enable their reuse
--
MOS_MIGRATED_REVID=103634406
23 files changed, 2114 insertions, 912 deletions
diff --git a/src/main/java/BUILD b/src/main/java/BUILD index ad8f48cb7d..6b01fff121 100644 --- a/src/main/java/BUILD +++ b/src/main/java/BUILD @@ -14,14 +14,18 @@ java_library( "com/google/devtools/build/lib/actions/**/*.java", ]), deps = [ + ":base-util", + ":clock", ":collect", ":common", ":concurrent", ":events", + ":io", ":options", ":packages", ":shell", ":skyframe-base", + ":util", ":vfs", "//src/main/protobuf:proto_extra_actions_base", "//third_party:guava", @@ -36,9 +40,11 @@ java_library( "com/google/devtools/build/lib/cmdline/*.java", ]), deps = [ + ":base-util", ":common", ":concurrent", ":syntax", + ":util", ":vfs", "//third_party:guava", "//third_party:jsr305", @@ -89,6 +95,7 @@ java_library( deps = [ ":common", ":concurrent", + ":io", ":vfs", "//third_party:guava", "//third_party:jsr305", @@ -119,11 +126,13 @@ java_library( name = "syntax", srcs = glob(["com/google/devtools/build/lib/syntax/*.java"]), deps = [ + ":base-util", ":collect", ":common", ":concurrent", ":events", ":options", + ":util", ":vfs", "//src/main/protobuf:proto_build", "//third_party:auto_value", @@ -150,6 +159,7 @@ java_library( ":events", ":options", ":syntax", + ":util", ":vfs", "//src/main/protobuf:proto_build", "//third_party:guava", @@ -176,16 +186,109 @@ java_library( name = "vfs", srcs = glob([ "com/google/devtools/build/lib/vfs/**/*.java", - "com/google/devtools/build/lib/profiler/**/*.java", - "com/google/devtools/build/lib/util/**/*.java", + "com/google/devtools/build/lib/profiler/*.java", ]), deps = [ + ":base-util", + ":clock", + ":common", + ":concurrent", + ":options", + ":os_util", + ":shell", + ":unix", + "//third_party:guava", + "//third_party:jsr305", + ], +) + +java_library( + name = "profiler-output", + srcs = glob([ + "com/google/devtools/build/lib/profiler/chart/*.java", + "com/google/devtools/build/lib/profiler/output/*.java", + "com/google/devtools/build/lib/profiler/statistics/*.java", + ]), + deps = [ + ":actions", + ":collect", + ":util", + ":vfs", + "//third_party:guava", + ], +) + +# Clock classes. +java_library( + name = "clock", + srcs = [ + "com/google/devtools/build/lib/util/BlazeClock.java", + "com/google/devtools/build/lib/util/Clock.java", + "com/google/devtools/build/lib/util/JavaClock.java", + ], + deps = [ + ":concurrent", + ], +) + +# String canonicalizer. +java_library( + name = "base-util", + srcs = [ + "com/google/devtools/build/lib/util/StringCanonicalizer.java", + "com/google/devtools/build/lib/util/StringTrie.java", + "com/google/devtools/build/lib/util/VarInt.java", + ], + deps = [ + ":common", + "//third_party:guava", + ], +) + +# I/O utilities. +java_library( + name = "io", + srcs = glob(["com/google/devtools/build/lib/util/io/*.java"]), + deps = [ + ":clock", + ":common", + ":concurrent", + ":vfs", + "//third_party:guava", + ], +) + +# General utilities. +java_library( + name = "os_util", + srcs = ["com/google/devtools/build/lib/util/OS.java"], +) + +java_library( + name = "util", + srcs = glob( + ["com/google/devtools/build/lib/util/*.java"], + exclude = [ + "com/google/devtools/build/lib/util/BlazeClock.java", + "com/google/devtools/build/lib/util/Clock.java", + "com/google/devtools/build/lib/util/JavaClock.java", + "com/google/devtools/build/lib/util/OS.java", + "com/google/devtools/build/lib/util/StringCanonicalizer.java", + "com/google/devtools/build/lib/util/StringTrie.java", + "com/google/devtools/build/lib/util/VarInt.java", + ], + ), + deps = [ + ":base-util", + ":clock", ":collect", ":common", ":concurrent", ":options", + ":os_util", ":shell", ":unix", + ":vfs", "//third_party:guava", "//third_party:jsr305", ], @@ -201,6 +304,7 @@ java_library( ":common", ":concurrent", ":events", + ":util", ":vfs", "//third_party:guava", "//third_party:jsr305", @@ -226,15 +330,19 @@ java_library( ], deps = [ ":actions", + ":base-util", ":collect", ":common", ":concurrent", ":events", ":graph", + ":io", ":options", + ":os_util", ":packages", ":shell", ":skyframe-base", + ":util", ":vfs", "//src/main/protobuf:proto_android_studio_ide_info", "//src/main/protobuf:proto_bundlemerge", @@ -269,6 +377,7 @@ java_library( ":query2", ":shell", ":skyframe-base", + ":util", ":vfs", "//src/main/protobuf:proto_crosstool_config", "//src/main/protobuf:proto_extra_actions_base", @@ -304,6 +413,7 @@ java_library( ":options", ":packages", ":skyframe-base", + ":util", ":vfs", "//src/main/protobuf:proto_build", "//third_party:guava", @@ -320,17 +430,22 @@ java_library( deps = [ ":actions", ":analysis-exec-rules-skyframe", + ":clock", ":collect", ":common", ":concurrent", ":docgen", ":events", + ":io", ":options", + ":os_util", ":packages", + ":profiler-output", ":query2", ":server", ":shell", ":skyframe-base", + ":util", ":vfs", "//src/main/protobuf:proto_build", "//src/main/protobuf:proto_test_status", @@ -350,7 +465,7 @@ java_library( ":common", ":concurrent", ":packages", - ":vfs", + ":util", "//third_party:apache_velocity", "//third_party:guava", ], @@ -366,18 +481,23 @@ java_library( deps = [ ":actions", ":analysis-exec-rules-skyframe", + ":clock", ":cmdline", ":collect", ":common", ":concurrent", ":docgen", ":events", + ":io", ":options", + ":os_util", ":packages", + ":profiler-output", ":query2", ":shell", ":skyframe-base", ":unix", + ":util", ":vfs", "//src/main/protobuf:proto_build", "//src/main/protobuf:proto_test_status", @@ -393,7 +513,10 @@ java_library( "com/google/devtools/build/lib/server/**/*.java", ]), deps = [ + ":clock", + ":io", ":unix", + ":util", ":vfs", "//third_party:guava", "//third_party:jsr305", @@ -408,10 +531,11 @@ java_library( deps = [ ":analysis-exec-rules-skyframe", ":buildtool-runtime", + ":clock", ":events", ":options", ":packages", - ":vfs", + ":util", "//src/main/protobuf:proto_test_status", "//third_party:gson", "//third_party:guava", @@ -457,20 +581,24 @@ java_library( ":actions", ":analysis-exec-rules-skyframe", ":buildtool-runtime", + ":clock", ":collect", ":common", ":concurrent", ":events", ":genquery", ":graph", + ":io", ":maven-connector", ":options", + ":os_util", ":packages", ":query2", ":runtime", ":shell", ":skyframe-base", ":unix", + ":util", ":vfs", ":webstatusserver", "//src/java_tools/singlejar:zip", @@ -579,7 +707,7 @@ java_library( ":common", ":concurrent", ":packages", - ":vfs", + ":util", "//third_party:apache_velocity", "//third_party:guava", "//third_party:jsr305", 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<ProfilerTask> 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<ProfilerTask> allSatisfying(Predicate<ProfilerTask> predicate) { + EnumSet<ProfilerTask> 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/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<String, Task> userFunctionTasks; - private final ListMultimap<String, Task> builtinFunctionTasks; - private final List<TasksStatistics> userFunctionStats; - private final List<TasksStatistics> 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<String, Task> tasks, List<TasksStatistics> stats) { - long total = 0L; - for (Entry<String, List<Task>> 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("<style type=\"text/css\"><!--"); - out.println("div.skylark-histogram {"); - out.println(" width: 95%; margin: 0 auto; display: none;"); - out.println("}"); - out.println("div.skylark-chart {"); - out.println(" width: 100%; height: 200px; margin: 0 auto 2em;"); - out.println("}"); - out.println("div.skylark-table {"); - out.println(" width: 95%; margin: 0 auto;"); - out.println("}"); - out.println("--></style>"); - - out.println("<script type=\"text/javascript\" src=\"https://www.google.com/jsapi\"></script>"); - out.println("<script type=\"text/javascript\">"); - out.println("google.load(\"visualization\", \"1.1\", {packages:[\"corechart\",\"table\"]});"); - out.println("google.setOnLoadCallback(drawVisualization);"); - - String dataVar = "data"; - String tableVar = dataVar + "Table"; - out.printf("var %s = {};\n", dataVar); - out.printf("var %s = {};\n", tableVar); - out.println("var histogramData;"); - - out.println("function drawVisualization() {"); - printStatsJs(userFunctionStats, "user", dataVar, tableVar, userTotalNanos); - printStatsJs(builtinFunctionStats, "builtin", dataVar, tableVar, builtinTotalNanos); - - printHistogramData(); - - out.println(" document.querySelector('#user-close').onclick = function() {"); - out.println(" document.querySelector('#user-histogram').style.display = 'none';"); - out.println(" };"); - out.println(" document.querySelector('#builtin-close').onclick = function() {"); - out.println(" document.querySelector('#builtin-histogram').style.display = 'none';"); - out.println(" };"); - out.println("};"); - - out.println("var options = {"); - out.println(" isStacked: true,"); - out.println(" legend: { position: 'none' },"); - out.println(" hAxis: { },"); - out.println(" histogram: { lastBucketPercentile: 5 },"); - out.println(" vAxis: { title: '# calls',"); - out.println(" viewWindowMode: 'pretty', gridlines: { count: -1 } }"); - out.println("};"); - - out.println("function selectHandler(category) {"); - out.println(" return function() {"); - out.printf(" var selection = %s[category].getSelection();\n", tableVar); - out.println(" if (selection.length < 1) return;"); - out.println(" var item = selection[0];"); - out.printf(" var loc = %s[category].getValue(item.row, 0);\n", dataVar); - out.printf(" var func = %s[category].getValue(item.row, 1);\n", dataVar); - out.println(" var key = loc + '#' + func;"); - out.println(" var histData = histogramData[category][key];"); - out.println(" var fnOptions = JSON.parse(JSON.stringify(options));"); - out.println(" fnOptions.title = loc + ' - ' + func;"); - out.println(" var chartDiv = document.getElementById(category+'-chart');"); - out.println(" var chart = new google.visualization.Histogram(chartDiv);"); - out.println(" var histogramDiv = document.getElementById(category+'-histogram');"); - out.println(" histogramDiv.style.display = 'block';"); - out.println(" chart.draw(histData, fnOptions);"); - out.println(" }"); - out.println("};"); - out.println("</script>"); - } - - private void printHistogramData() { - out.println(" histogramData = {"); - printHistogramData(builtinFunctionTasks, "builtin"); - printHistogramData(userFunctionTasks, "user"); - out.println(" }"); - } - - private void printHistogramData(ListMultimap<String, Task> 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<TasksStatistics> 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 = '<i>No relevant function calls to display. Some minor" - + " builtin functions may have been ignored because their names could not be used as" - + " variables in JavaScript.</i>'"); - } else { - 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("<a name='skylark_stats'/>"); - out.println("<h3>Skylark Statistics</h3>"); - out.println("<h4>User-Defined function execution time</h4>"); - out.println("<div class=\"skylark-histogram\" id=\"user-histogram\">"); - out.println(" <div class=\"skylark-chart\" id=\"user-chart\"></div>"); - out.println(" <button id=\"user-close\">Hide histogram</button>"); - out.println("</div>"); - out.println("<div class=\"skylark-table\" id=\"user_function_stats\"></div>"); - - out.println("<h4>Builtin function execution time</h4>"); - out.println("<div class=\"skylark-histogram\" id=\"builtin-histogram\">"); - out.println(" <div class=\"skylark-chart\" id=\"builtin-chart\"></div>"); - out.println(" <button id=\"builtin-close\">Hide histogram</button>"); - out.println("</div>"); - out.println("<div class=\"skylark-table\" id=\"builtin_function_stats\"></div>"); - } - - /** - * Computes a string keeping the structure of the input but reducing the amount of characters on - * elements at the front if necessary. - * - * <p>Reduces the length of function location strings by keeping at least the last element fully - * intact and at most {@link SkylarkStatistics#NUM_LOCATION_CHARS_UNABBREVIATED} from other - * elements from the end. Elements before are abbreviated with their first two characters. - * - * <p>Example: - * "//source/tree/with/very/descriptive/and/long/hierarchy/of/directories/longfilename.bzl:42" - * becomes: "//so/tr/wi/ve/de/an/lo/hierarch/of/directories/longfilename.bzl:42" - * - * <p>There is no fixed length to the result as the last element is kept and the location may - * have many elements. - * - * @param location Either a sequence of path elements separated by - * {@link StandardSystemProperty#FILE_SEPARATOR} and preceded by some root element - * (e.g. "/", "C:\") or path elements separated by "." and having no root element. - */ - private String abbreviatePath(String location) { - String[] elements; - int lowestAbbreviateIndex; - String root; - String separator = StandardSystemProperty.FILE_SEPARATOR.value(); - if (location.contains(separator)) { - elements = location.split(separator); - // must take care to preserve file system roots (e.g. "/", "C:\"), keep separate - lowestAbbreviateIndex = 1; - root = location.substring(0, location.indexOf(separator) + 1); - } else { - // must be java class name for a builtin function - elements = location.split("\\."); - lowestAbbreviateIndex = 0; - root = ""; - separator = "."; - } - - String last = elements[elements.length - 1]; - int remaining = NUM_LOCATION_CHARS_UNABBREVIATED - last.length(); - // start from the next to last element of the location and add until "remaining" many - // chars added, abbreviate rest with first 2 characters - for (int index = elements.length - 2; index >= lowestAbbreviateIndex; index--) { - String element = elements[index]; - if (remaining > 0) { - int length = Math.min(remaining, element.length()); - element = element.substring(0, length); - remaining -= length; - } else { - element = element.substring(0, Math.min(2, element.length())); - } - elements[index] = element; - } - return root + Joiner.on(separator).join(Arrays.asList(elements).subList(1, elements.length)); - } -} diff --git a/src/main/java/com/google/devtools/build/lib/profiler/output/CriticalPathText.java b/src/main/java/com/google/devtools/build/lib/profiler/output/CriticalPathText.java new file mode 100644 index 0000000000..b82778f5f9 --- /dev/null +++ b/src/main/java/com/google/devtools/build/lib/profiler/output/CriticalPathText.java @@ -0,0 +1,173 @@ +// Copyright 2015 Google Inc. All rights reserved. +// +// Licensed under the Apache License, Version 2.0 (the "License"); +// you may not use this file except in compliance with the License. +// You may obtain a copy of the License at +// +// http://www.apache.org/licenses/LICENSE-2.0 +// +// Unless required by applicable law or agreed to in writing, software +// distributed under the License is distributed on an "AS IS" BASIS, +// WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. +// See the License for the specific language governing permissions and +// limitations under the License. +package com.google.devtools.build.lib.profiler.output; + +import com.google.devtools.build.lib.actions.MiddlemanAction; +import com.google.devtools.build.lib.profiler.ProfileInfo.CriticalPathEntry; +import com.google.devtools.build.lib.profiler.statistics.CriticalPathStatistics; +import com.google.devtools.build.lib.util.Pair; +import com.google.devtools.build.lib.util.TimeUtilities; + +import java.io.PrintStream; + +/** + * Generate textual output from {@link CriticalPathStatistics}. + */ +//TODO(bazel-team): Also print remote vs build stats recorded by Logging.CriticalPathStats +public final class CriticalPathText extends TextPrinter { + + private final CriticalPathStatistics criticalPathStats; + private long executionTime; + + public CriticalPathText( + PrintStream out, CriticalPathStatistics critPathStats, long executionTime) { + super(out); + this.criticalPathStats = critPathStats; + this.executionTime = executionTime; + } + + public void printTimingBreakdown() { + CriticalPathEntry totalPath = criticalPathStats.getTotalPath(); + CriticalPathEntry optimalPath = criticalPathStats.getOptimalPath(); + if (totalPath != null) { + if (!totalPath.isComponent()) { + printCriticalPathTimingBreakdown(totalPath, optimalPath); + } + } else { + lnPrint("Critical path not available because no action graph was generated."); + } + } + + void printCriticalPathTimingBreakdown( + CriticalPathEntry totalPath, CriticalPathEntry optimalPath) { + lnPrint(totalPath.task.type); + + lnPrintf( + TWO_COLUMN_FORMAT, + "Worker thread scheduling delays", + TimeUtilities.prettyTime(criticalPathStats.getWorkerWaitTime())); + lnPrintf( + TWO_COLUMN_FORMAT, + "Main thread scheduling delays", + TimeUtilities.prettyTime(criticalPathStats.getMainThreadWaitTime())); + + printLn(); + lnPrint("Critical path time:"); + + long totalTime = totalPath.cumulativeDuration; + lnPrintf( + "%-37s %10s (%s of execution time)", + "Actual time", + TimeUtilities.prettyTime(totalTime), + prettyPercentage((double) totalTime / executionTime)); + + long optimalTime = optimalPath.cumulativeDuration; + lnPrintf( + "%-37s %10s (%s of execution time)", + "Time excluding scheduling delays", + TimeUtilities.prettyTime(optimalTime), + prettyPercentage((double) optimalTime / executionTime)); + + printLn(); + // Artificial critical path if we ignore all the time spent in all tasks, + // except time directly attributed to the ACTION tasks. + lnPrint("Time related to:"); + + for (Pair<String, Double> relativePathDuration : criticalPathStats) { + lnPrintf( + TWO_COLUMN_FORMAT, + relativePathDuration.first, + prettyPercentage(relativePathDuration.second)); + } + } + + /** + * Print total and optimal critical paths if available. + */ + public void printCriticalPaths() { + CriticalPathEntry totalPath = criticalPathStats.getTotalPath(); + printCriticalPath("Critical path", totalPath); + // In critical path components we do not record scheduling delay data so it does not make + // sense to differentiate it. + if (!totalPath.isComponent()) { + printCriticalPath( + "Critical path excluding scheduling delays", criticalPathStats.getOptimalPath()); + } + } + + private void printCriticalPath(String title, CriticalPathEntry path) { + lnPrintf("%s (%s):", title, TimeUtilities.prettyTime(path.cumulativeDuration)); + + boolean isComponent = path.isComponent(); + if (isComponent) { + lnPrintf("%6s %11s %8s %s", "Id", "Time", "Percentage", "Description"); + } else { + lnPrintf("%6s %11s %8s %8s %s", "Id", "Time", "Share", "Critical", "Description"); + } + + long totalPathTime = path.cumulativeDuration; + int middlemanCount = 0; + long middlemanDuration = 0L; + long middlemanCritTime = 0L; + + for (; path != null; path = path.next) { + if (path.task.id < 0) { + // Ignore fake actions. + continue; + } else if (path.task.getDescription().startsWith(MiddlemanAction.MIDDLEMAN_MNEMONIC + " ") + || path.task.getDescription().startsWith("TargetCompletionMiddleman")) { + // Aggregate middleman actions. + middlemanCount++; + middlemanDuration += path.duration; + middlemanCritTime += path.getCriticalTime(); + } else { + String desc = path.task.getDescription().replace(':', ' '); + if (isComponent) { + lnPrintf( + "%6d %11s %8s %s", + path.task.id, + TimeUtilities.prettyTime(path.duration), + prettyPercentage((double) path.duration / totalPathTime), + desc); + } else { + lnPrintf( + "%6d %11s %8s %8s %s", + path.task.id, + TimeUtilities.prettyTime(path.duration), + prettyPercentage((double) path.duration / totalPathTime), + prettyPercentage((double) path.getCriticalTime() / totalPathTime), + desc); + } + } + } + if (middlemanCount > 0) { + if (isComponent) { + lnPrintf( + " %11s %8s [%d middleman actions]", + TimeUtilities.prettyTime(middlemanDuration), + prettyPercentage((double) middlemanDuration / totalPathTime), + middlemanCount); + } else { + lnPrintf( + " %11s %8s %8s [%d middleman actions]", + TimeUtilities.prettyTime(middlemanDuration), + prettyPercentage((double) middlemanDuration / totalPathTime), + prettyPercentage((double) middlemanCritTime / totalPathTime), + middlemanCount); + } + } + } +} + + diff --git a/src/main/java/com/google/devtools/build/lib/profiler/chart/HtmlCreator.java b/src/main/java/com/google/devtools/build/lib/profiler/output/HtmlCreator.java index 899e339d4c..45519cc183 100644 --- a/src/main/java/com/google/devtools/build/lib/profiler/chart/HtmlCreator.java +++ b/src/main/java/com/google/devtools/build/lib/profiler/output/HtmlCreator.java @@ -11,57 +11,60 @@ // 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; +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.ProfilePhaseStatistics; +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.List; +import java.util.EnumMap; /** * Creates an HTML page displaying the various statistics and charts generated * from the profile file. */ -public final class HtmlCreator { +public final class HtmlCreator extends HtmlPrinter { - private final PrintStream out; private final Chart chart; private final HtmlChartVisitor chartVisitor; - private final Optional<SkylarkStatistics> skylarkStats; + private final Optional<SkylarkHtml> skylarkStats; private final String title; - - /** - * Pre-formatted statistics for each phase of the profiled build. - */ - private final List<ProfilePhaseStatistics> statistics; + private final PhaseHtml phases; private HtmlCreator( PrintStream out, String title, Chart chart, - Optional<SkylarkStatistics> skylarkStats, + Optional<SkylarkHtml> skylarkStats, int htmlPixelsPerSecond, - List<ProfilePhaseStatistics> statistics) { - this.out = out; + PhaseHtml phases) { + super(out); this.title = title; this.chart = chart; chartVisitor = new HtmlChartVisitor(out, htmlPixelsPerSecond); this.skylarkStats = skylarkStats; - this.statistics = statistics; + this.phases = phases; } private void print() { htmlFrontMatter(); chart.accept(chartVisitor); - out.println("<h2>Statistics</h2>"); - printPhaseStatistics(); + element("a", "name", "Statistics"); + element("h2", "Statistics"); + phases.print(); if (skylarkStats.isPresent()) { skylarkStats.get().printHtmlBody(); @@ -70,72 +73,55 @@ public final class HtmlCreator { } private void htmlFrontMatter() { - out.println("<html><head>"); - out.printf("<title>%s</title>", title); + lnOpen("html"); + lnOpen("head"); + lnElement("title", title); chartVisitor.printCss(chart.getSortedTypes()); + phases.printCss(); + if (skylarkStats.isPresent()) { skylarkStats.get().printHtmlHead(); } - out.println("</head>"); - out.println("<body>"); - out.printf("<h1>%s</h1>\n", title); + lnClose(); + lnOpen("body"); + lnElement("h1", title); } private void htmlBackMatter() { - out.println("</body>"); - out.println("</html>"); - } - - /** - * Print a table from {@link #statistics} arranging the phases side by side. - */ - private void printPhaseStatistics() { - out.println("<table border=\"0\" width=\"100%\"><tr>"); - String statsSeparator = ""; - for (ProfilePhaseStatistics stat : statistics) { - out.println(statsSeparator); - out.println("<td valign=\"top\" style=\"margin: 0 10 0;\">"); - String title = stat.getTitle(); - if (!title.isEmpty()) { - out.println(String.format("<h3>%s</h3>", title)); - } - out.println("<pre>" + stat.getStatistics() + "</pre></td>"); - statsSeparator = "<td><div style=\"width:20px;\"> </div></td>"; - } - out.println("</tr></table>"); + lnClose(); + lnClose(); } /** * Writes the HTML profiling information. - * @param info - * @param htmlFile - * @param statistics - * @param detailed - * @param htmlPixelsPerSecond + * * @throws IOException */ - public static void createHtml( + public static void create( ProfileInfo info, Path htmlFile, - List<ProfilePhaseStatistics> statistics, + PhaseSummaryStatistics phaseSummaryStats, + EnumMap<ProfilePhase, PhaseStatistics> statistics, boolean detailed, - int htmlPixelsPerSecond) + int htmlPixelsPerSecond, + int vfsStatsLimit) throws IOException { try (PrintStream out = new PrintStream(new BufferedOutputStream(htmlFile.getOutputStream()))) { ChartCreator chartCreator; - Optional<SkylarkStatistics> skylarkStats; + PhaseHtml phaseHtml = new PhaseHtml(out, phaseSummaryStats, statistics, vfsStatsLimit); + Optional<SkylarkHtml> skylarkStats; if (detailed) { + skylarkStats = Optional.of(new SkylarkHtml(out, new SkylarkStatistics(info))); chartCreator = new DetailedChartCreator(info); - 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(); + new HtmlCreator(out, info.comment, chart, skylarkStats, htmlPixelsPerSecond, phaseHtml) + .print(); } } } diff --git a/src/main/java/com/google/devtools/build/lib/profiler/output/HtmlPrinter.java b/src/main/java/com/google/devtools/build/lib/profiler/output/HtmlPrinter.java new file mode 100644 index 0000000000..531e0f6fa0 --- /dev/null +++ b/src/main/java/com/google/devtools/build/lib/profiler/output/HtmlPrinter.java @@ -0,0 +1,104 @@ +// Copyright 2015 Google Inc. All rights reserved. +// +// Licensed under the Apache License, Version 2.0 (the "License"); +// you may not use this file except in compliance with the License. +// You may obtain a copy of the License at +// +// http://www.apache.org/licenses/LICENSE-2.0 +// +// Unless required by applicable law or agreed to in writing, software +// distributed under the License is distributed on an "AS IS" BASIS, +// WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. +// See the License for the specific language governing permissions and +// limitations under the License. +package com.google.devtools.build.lib.profiler.output; + +import java.io.PrintStream; +import java.util.ArrayDeque; +import java.util.Deque; + +/** + * Utility function for writing HTML data to a {@link PrintStream}. + */ +public abstract class HtmlPrinter extends TextPrinter { + + private Deque<String> currentlyOpenTags; + + protected HtmlPrinter(PrintStream out) { + super(out); + currentlyOpenTags = new ArrayDeque<>(); + } + + /** + * Print an open tag with attributes and possibly content and increase indentation level. + * + * <p>All array elements are taken in pairs for attributes and their values. If odd, the last + * element is taken as the content of the element. It is printed directly after the opening tag. + * @param attributesAndContent must have the form: attribute1, value1, attribute2, value2, ..., + * content + */ + protected void open(String tag, Object... attributesAndContent) { + printf("<%s", tag); + for (int index = 0; index < attributesAndContent.length - 1; index += 2) { + printf(" %s=\"%s\"", attributesAndContent[index], attributesAndContent[index + 1]); + } + print(">"); + if (attributesAndContent.length % 2 == 1) { + print(attributesAndContent[attributesAndContent.length - 1]); + } + down(); + currentlyOpenTags.addFirst(tag); + } + + /** + * Print a newline, an open tag with attributes and possibly content and increase indentation + * level + * @see #open(String, Object...) + */ + protected void lnOpen(String tag, Object... attributes) { + lnIndent(); + open(tag, attributes); + } + + /** + * Decrease indentation level and close the most recently opened tag + */ + protected void close() { + up(); + printf("</%s>", currentlyOpenTags.pop()); + } + + /** + * Decrease indentation level, print newline, indentation and close the most recently opened tag + */ + protected void lnClose() { + up(); + lnPrintf("</%s>", currentlyOpenTags.pop()); + } + + protected void lnElement(String tag, Object content) { + lnIndent(); + element(tag, content); + } + + /** + * Print a single element with attributes and possibly content. + * + * @see #open(String, Object...) + */ + protected void element(String tag, Object... attributesAndContent) { + open(tag, attributesAndContent); + close(); + } + + /** + * Print a newline, indent and a single element with attributes and possibly content. + * + * @see #lnOpen(String, Object...) + */ + protected void lnElement(String tag, Object... attributesAndContent) { + lnOpen(tag, attributesAndContent); + close(); + } +} + diff --git a/src/main/java/com/google/devtools/build/lib/profiler/output/PhaseHtml.java b/src/main/java/com/google/devtools/build/lib/profiler/output/PhaseHtml.java new file mode 100644 index 0000000000..f6e1cba255 --- /dev/null +++ b/src/main/java/com/google/devtools/build/lib/profiler/output/PhaseHtml.java @@ -0,0 +1,208 @@ +// Copyright 2015 Google Inc. All rights reserved. +// +// Licensed under the Apache License, Version 2.0 (the "License"); +// you may not use this file except in compliance with the License. +// You may obtain a copy of the License at +// +// http://www.apache.org/licenses/LICENSE-2.0 +// +// Unless required by applicable law or agreed to in writing, software +// distributed under the License is distributed on an "AS IS" BASIS, +// WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. +// See the License for the specific language governing permissions and +// limitations under the License. +package com.google.devtools.build.lib.profiler.output; + +import com.google.devtools.build.lib.profiler.ProfilePhase; +import com.google.devtools.build.lib.profiler.ProfilerTask; +import com.google.devtools.build.lib.profiler.statistics.PhaseStatistics; +import com.google.devtools.build.lib.profiler.statistics.PhaseSummaryStatistics; +import com.google.devtools.build.lib.profiler.statistics.PhaseVfsStatistics; +import com.google.devtools.build.lib.profiler.statistics.PhaseVfsStatistics.Stat; +import com.google.devtools.build.lib.util.StringUtil; +import com.google.devtools.build.lib.util.TimeUtilities; + +import java.io.PrintStream; +import java.util.Arrays; +import java.util.EnumMap; +import java.util.Map.Entry; + +/** + * Output {@link PhaseSummaryStatistics}, {@link PhaseStatistics} and {@link PhaseVfsStatistics} + * in HTML format. + */ +public final class PhaseHtml extends HtmlPrinter { + + private final PhaseSummaryStatistics phaseSummaryStats; + private final EnumMap<ProfilePhase, PhaseStatistics> phaseStatistics; + private final int vfsStatsLimit; + + /** + * @param vfsStatsLimit maximum number of VFS statistics to print, or -1 for no limit. + */ + public PhaseHtml( + PrintStream out, + PhaseSummaryStatistics phaseSummaryStats, + EnumMap<ProfilePhase, PhaseStatistics> phaseStatistics, + int vfsStatsLimit) { + super(out); + this.phaseSummaryStats = phaseSummaryStats; + this.phaseStatistics = phaseStatistics; + this.vfsStatsLimit = vfsStatsLimit; + } + + /** + * Output a style tag with all necessary CSS directives + */ + public void printCss() { + lnPrint("<style type=\"text/css\"><!--"); + down(); + lnPrint("div.phase-statistics {"); + lnPrint(" margin: 0 10;"); + lnPrint(" font-size: small;"); + lnPrint(" font-family: monospace;"); + lnPrint(" float: left;"); + lnPrint("}"); + lnPrint("table.phase-statistics {"); + lnPrint(" border: 0px; text-align: right;"); + lnPrint("}"); + lnPrint("table.phase-statistics td {"); + lnPrint(" padding: 0 5;"); + lnPrint("}"); + lnPrint("td.left {"); + lnPrint(" text-align: left;"); + lnPrint("}"); + lnPrint("td.center {"); + lnPrint(" text-align: center;"); + lnPrint("}"); + up(); + lnPrint("--></style>"); + } + + /** + * Print tables from {@link #phaseSummaryStats} and {@link #phaseStatistics} side by side. + */ + public void print() { + printPhaseSummaryStatistics(); + + for (ProfilePhase phase : + Arrays.asList(ProfilePhase.INIT, ProfilePhase.LOAD, ProfilePhase.ANALYZE)) { + PhaseStatistics statistics = phaseStatistics.get(phase); + if (!statistics.wasExecuted()) { + continue; + } + printPhaseStatistics(statistics); + } + lnElement("div", "style", "clear: both;"); + } + + /** + * Print header and tables for a single phase. + */ + private void printPhaseStatistics(PhaseStatistics phaseStat) { + lnOpen("div", "class", "phase-statistics"); + lnElement( + "h3", + String.format( + "%s Phase Information", StringUtil.capitalize(phaseStat.getProfilePhase().nick))); + lnOpen("table", "class", "phase-statistics"); + lnOpen("tr"); + open("td", "class", "left", "colspan", "3"); + printf("Total %s phase time", phaseStat.getProfilePhase().nick); + close(); // td + element("td", TimeUtilities.prettyTime(phaseStat.getPhaseDurationNanos())); + lnClose(); // tr + + if (!phaseStat.isEmpty()) { + lnOpen("tr"); + element("td", "class", "left", "colspan", "4", "Total time (across all threads) spent on:"); + close(); // tr + lnOpen("tr"); + element("td", "Type"); + element("td", "Total"); + element("td", "Count"); + element("td", "Average"); + close(); // tr + for (ProfilerTask taskType : phaseStat) { + lnOpen("tr", "class", "phase-task-statistics"); + element("td", taskType); + element("td", prettyPercentage(phaseStat.getTotalRelativeDuration(taskType))); + element("td", phaseStat.getCount(taskType)); + element("td", TimeUtilities.prettyTime(phaseStat.getMeanDuration(taskType))); + close(); // tr + } + } + lnClose(); // table + printVfsStatistics(phaseStat.getVfsStatistics()); + lnClose(); // div + } + + /** + * Print the time spent on VFS operations on each path. Output is grouped by operation and sorted + * by descending duration. If multiple of the same VFS operation were logged for the same path, + * print the total duration. + */ + private void printVfsStatistics(PhaseVfsStatistics stats) { + if (vfsStatsLimit == 0 || stats.isEmpty()) { + return; + } + + lnElement("h4", "VFS path statistics:"); + + lnOpen("table", "class", "phase-statistics"); + lnOpen("tr"); + element("td", "Type"); + element("td", "Frequency"); + element("td", "Duration"); + element("td", "class", "left", "Path"); + close(); // tr + + for (ProfilerTask type : stats) { + int numPrinted = 0; + for (Entry<Stat, String> stat : stats.getSortedStatistics(type)) { + lnOpen("tr"); + if (vfsStatsLimit != -1 && numPrinted++ == vfsStatsLimit) { + open("td", "class", "center", "colspan", "4"); + printf("... %d more ...", stats.getStatisticsCount(type) - vfsStatsLimit); + close(); + close(); // tr + break; + } + element("td", type.name()); + element("td", stat.getKey().count); + element("td", TimeUtilities.prettyTime(stat.getKey().duration)); + element("td", "class", "left", stat.getValue()); + close(); // tr + } + } + + lnClose(); // table + } + + /** + * Print a table for the phase overview with runtime and runtime percentage per phase and total. + */ + private void printPhaseSummaryStatistics() { + lnOpen("div", "class", "phase-statistics"); + lnElement("h3", "Phase Summary Information"); + lnOpen("table", "class", "phase-statistics"); + for (ProfilePhase phase : phaseSummaryStats) { + lnOpen("tr"); + lnOpen("td", "class", "left"); + printf("Total %s phase time", phase.nick); + close(); + element("td", TimeUtilities.prettyTime(phaseSummaryStats.getDurationNanos(phase))); + element("td", phaseSummaryStats.getPrettyPercentage(phase)); + lnClose(); // tr + } + lnOpen("tr"); + lnElement("td", "class", "left", "Total run time"); + element("td", TimeUtilities.prettyTime(phaseSummaryStats.getTotalDuration())); + element("td", "100.00%"); + lnClose(); // tr + lnClose(); // table + lnClose(); // div + } +} + + diff --git a/src/main/java/com/google/devtools/build/lib/profiler/output/PhaseText.java b/src/main/java/com/google/devtools/build/lib/profiler/output/PhaseText.java new file mode 100644 index 0000000000..6157fbb5f6 --- /dev/null +++ b/src/main/java/com/google/devtools/build/lib/profiler/output/PhaseText.java @@ -0,0 +1,219 @@ +// Copyright 2015 Google Inc. All rights reserved. +// +// Licensed under the Apache License, Version 2.0 (the "License"); +// you may not use this file except in compliance with the License. +// You may obtain a copy of the License at +// +// http://www.apache.org/licenses/LICENSE-2.0 +// +// Unless required by applicable law or agreed to in writing, software +// distributed under the License is distributed on an "AS IS" BASIS, +// WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. +// See the License for the specific language governing permissions and +// limitations under the License. +package com.google.devtools.build.lib.profiler.output; + +import com.google.devtools.build.lib.profiler.ProfilePhase; +import com.google.devtools.build.lib.profiler.ProfilerTask; +import com.google.devtools.build.lib.profiler.statistics.CriticalPathStatistics; +import com.google.devtools.build.lib.profiler.statistics.PhaseStatistics; +import com.google.devtools.build.lib.profiler.statistics.PhaseSummaryStatistics; +import com.google.devtools.build.lib.profiler.statistics.PhaseVfsStatistics; +import com.google.devtools.build.lib.profiler.statistics.PhaseVfsStatistics.Stat; +import com.google.devtools.build.lib.util.TimeUtilities; + +import java.io.PrintStream; +import java.util.Arrays; +import java.util.EnumMap; +import java.util.Map.Entry; + +/** + * Output {@link PhaseSummaryStatistics}, {@link PhaseStatistics} and {@link PhaseVfsStatistics} + * in text format. + */ +public final class PhaseText extends TextPrinter { + + private final PhaseSummaryStatistics phaseSummaryStats; + private final EnumMap<ProfilePhase, PhaseStatistics> phaseStatistics; + private final CriticalPathStatistics criticalPathStatistics; + private final int vfsStatsLimit; + private final int missingActionsCount; + + /** + * @param vfsStatsLimit maximum number of VFS statistics to print, or -1 for no limit. + */ + public PhaseText( + PrintStream out, + PhaseSummaryStatistics phaseSummaryStats, + EnumMap<ProfilePhase, PhaseStatistics> phaseStatistics, + CriticalPathStatistics critPathStats, + int missingActionsCount, + int vfsStatsLimit) { + super(out); + this.phaseSummaryStats = phaseSummaryStats; + this.phaseStatistics = phaseStatistics; + this.criticalPathStatistics = critPathStats; + this.missingActionsCount = missingActionsCount; + this.vfsStatsLimit = vfsStatsLimit; + } + + public void print() { + printPhaseSummaryStatistics(); + + for (ProfilePhase phase : + Arrays.asList(ProfilePhase.INIT, ProfilePhase.LOAD, ProfilePhase.ANALYZE)) { + PhaseStatistics statistics = phaseStatistics.get(phase); + if (statistics.wasExecuted()) { + printPhaseStatistics(statistics); + } + } + printExecutionPhaseStatistics(); + } + + /** + * Print a table for the phase overview with runtime and runtime percentage per phase and total. + */ + private void printPhaseSummaryStatistics() { + print("\n=== PHASE SUMMARY INFORMATION ===\n"); + for (ProfilePhase phase : phaseSummaryStats) { + long phaseDuration = phaseSummaryStats.getDurationNanos(phase); + double relativeDuration = phaseSummaryStats.getRelativeDuration(phase); + lnPrintf( + THREE_COLUMN_FORMAT, + "Total " + phase.nick + " phase time", + TimeUtilities.prettyTime(phaseDuration), + prettyPercentage(relativeDuration)); + } + lnPrintf( + THREE_COLUMN_FORMAT, + "Total run time", + TimeUtilities.prettyTime(phaseSummaryStats.getTotalDuration()), + "100.00%"); + printLn(); + } + + /** + * Prints all statistics from {@link PhaseStatistics} in text form. + */ + private void printPhaseStatistics(PhaseStatistics stats) { + lnPrintf("=== %s PHASE INFORMATION ===\n", stats.getProfilePhase().nick.toUpperCase()); + + lnPrintf( + TWO_COLUMN_FORMAT, + "Total " + stats.getProfilePhase().nick + " phase time", + TimeUtilities.prettyTime(stats.getPhaseDurationNanos())); + printLn(); + + if (!stats.isEmpty()) { + printTimingDistribution(stats); + printLn(); + if (vfsStatsLimit != 0) { + printVfsStatistics(stats.getVfsStatistics()); + printLn(); + } + } + } + + private void printExecutionPhaseStatistics() { + PhaseStatistics prepPhase = phaseStatistics.get(ProfilePhase.PREPARE); + PhaseStatistics execPhase = phaseStatistics.get(ProfilePhase.EXECUTE); + PhaseStatistics finishPhase = phaseStatistics.get(ProfilePhase.FINISH); + if (!execPhase.wasExecuted()) { + return; + } + lnPrint("=== EXECUTION PHASE INFORMATION ===\n"); + + long graphTime = execPhase.getTotalDurationNanos(ProfilerTask.ACTION_GRAPH); + long execTime = execPhase.getPhaseDurationNanos() - graphTime; + + if (prepPhase.wasExecuted()) { + lnPrintf( + TWO_COLUMN_FORMAT, + "Total preparation time", + TimeUtilities.prettyTime(prepPhase.getPhaseDurationNanos())); + } + lnPrintf( + TWO_COLUMN_FORMAT, + "Total execution phase time", + TimeUtilities.prettyTime(execPhase.getPhaseDurationNanos())); + if (finishPhase.wasExecuted()) { + lnPrintf( + TWO_COLUMN_FORMAT, + "Total time finalizing build", + TimeUtilities.prettyTime(finishPhase.getPhaseDurationNanos())); + } + printLn(); + lnPrintf( + TWO_COLUMN_FORMAT, "Action dependency map creation", TimeUtilities.prettyTime(graphTime)); + lnPrintf(TWO_COLUMN_FORMAT, "Actual execution time", TimeUtilities.prettyTime(execTime)); + + CriticalPathText criticalPaths = new CriticalPathText(out, criticalPathStatistics, execTime); + criticalPaths.printTimingBreakdown(); + printLn(); + + printTimingDistribution(execPhase); + printLn(); + + criticalPaths.printCriticalPaths(); + printLn(); + + if (missingActionsCount > 0) { + lnPrint(missingActionsCount); + print( + " action(s) are present in the" + + " action graph but missing instrumentation data. Most likely the profile file" + + " has been created during a failed or aborted build."); + printLn(); + } + + if (vfsStatsLimit != 0) { + printVfsStatistics(execPhase.getVfsStatistics()); + printLn(); + } + } + + /** + * Prints a table of task types and their relative total and average execution time as well as + * how many tasks of each type there were + */ + private void printTimingDistribution(PhaseStatistics stats) { + lnPrint("Total time (across all threads) spent on:"); + lnPrintf("%18s %8s %8s %11s", "Type", "Total", "Count", "Average"); + for (ProfilerTask type : stats) { + lnPrintf( + "%18s %8s %8d %11s", + type.toString(), + prettyPercentage(stats.getTotalRelativeDuration(type)), + stats.getCount(type), + TimeUtilities.prettyTime(stats.getMeanDuration(type))); + } + } + + /** + * Print the time spent on VFS operations on each path. Output is grouped by operation and + * sorted by descending duration. If multiple of the same VFS operation were logged for the same + * path, print the total duration. + */ + private void printVfsStatistics(PhaseVfsStatistics stats) { + lnPrint("VFS path statistics:"); + lnPrintf("%15s %10s %10s %s", "Type", "Frequency", "Duration", "Path"); + + for (ProfilerTask type : stats) { + int numPrinted = 0; + for (Entry<Stat, String> stat : stats.getSortedStatistics(type)) { + if (vfsStatsLimit != -1 && numPrinted++ == vfsStatsLimit) { + lnPrintf("... %d more ...", stats.getStatisticsCount(type) - vfsStatsLimit); + break; + } + lnPrintf( + "%15s %10d %10s %s", + type.name(), + stat.getKey().count, + TimeUtilities.prettyTime(stat.getKey().duration), + stat.getValue()); + } + } + } +} + + diff --git a/src/main/java/com/google/devtools/build/lib/profiler/output/SkylarkHtml.java b/src/main/java/com/google/devtools/build/lib/profiler/output/SkylarkHtml.java new file mode 100644 index 0000000000..e073dde633 --- /dev/null +++ b/src/main/java/com/google/devtools/build/lib/profiler/output/SkylarkHtml.java @@ -0,0 +1,299 @@ +// Copyright 2015 Google Inc. All rights reserved. +// +// Licensed under the Apache License, Version 2.0 (the "License"); +// you may not use this file except in compliance with the License. +// You may obtain a copy of the License at +// +// http://www.apache.org/licenses/LICENSE-2.0 +// +// Unless required by applicable law or agreed to in writing, software +// distributed under the License is distributed on an "AS IS" BASIS, +// WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. +// See the License for the specific language governing permissions and +// limitations under the License. +package com.google.devtools.build.lib.profiler.output; + +import com.google.common.base.Joiner; +import com.google.common.base.StandardSystemProperty; +import com.google.common.collect.ListMultimap; +import com.google.devtools.build.lib.profiler.ProfileInfo.Task; +import com.google.devtools.build.lib.profiler.statistics.SkylarkStatistics; +import com.google.devtools.build.lib.profiler.statistics.TasksStatistics; + +import java.io.PrintStream; +import java.util.Arrays; +import java.util.List; + +/** + * Formats {@link SkylarkStatistics} as a HTML tables and histogram charts. + */ +public final class SkylarkHtml extends HtmlPrinter { + + /** + * How many characters from the end of the location of a Skylark function to display. + */ + private static final int NUM_LOCATION_CHARS_UNABBREVIATED = 40; + + private final SkylarkStatistics stats; + + public SkylarkHtml(PrintStream out, SkylarkStatistics stats) { + super(out); + this.stats = stats; + } + + /** + * Prints all CSS definitions and JavaScript code. May be a large amount of output. + */ + void printHtmlHead() { + lnOpen("style", "type", "text/css", "<!--"); + lnPrint("div.skylark-histogram {"); + lnPrint(" width: 95%; margin: 0 auto; display: none;"); + lnPrint("}"); + lnPrint("div.skylark-chart {"); + lnPrint(" width: 100%; height: 200px; margin: 0 auto 2em;"); + lnPrint("}"); + lnPrint("div.skylark-table {"); + lnPrint(" width: 95%; margin: 0 auto;"); + lnPrint("}"); + lnPrint("-->"); + close(); // style + + lnElement("script", "type", "text/javascript", "src", "https://www.google.com/jsapi"); + lnOpen("script", "type", "text/javascript"); + lnPrint("google.load(\"visualization\", \"1.1\", {packages:[\"corechart\",\"table\"]});"); + lnPrint("google.setOnLoadCallback(drawVisualization);"); + + String dataVar = "data"; + String tableVar = dataVar + "Table"; + lnPrintf("var %s = {};\n", dataVar); + lnPrintf("var %s = {};\n", tableVar); + lnPrint("var histogramData;"); + + lnPrint("function drawVisualization() {"); + down(); + printStatsJs( + stats.getUserFunctionStats(), "user", dataVar, tableVar, stats.getUserTotalNanos()); + printStatsJs( + stats.getBuiltinFunctionStats(), + "builtin", + dataVar, + tableVar, + stats.getBuiltinTotalNanos()); + + printHistogramData(); + + lnPrint("document.querySelector('#user-close').onclick = function() {"); + lnPrint(" document.querySelector('#user-histogram').style.display = 'none';"); + lnPrint("};"); + lnPrint("document.querySelector('#builtin-close').onclick = function() {"); + lnPrint(" document.querySelector('#builtin-histogram').style.display = 'none';"); + lnPrint("};"); + up(); + lnPrint("};"); + + lnPrint("var options = {"); + down(); + lnPrint("isStacked: true,"); + lnPrint("legend: { position: 'none' },"); + lnPrint("hAxis: { },"); + lnPrint("histogram: { lastBucketPercentile: 5 },"); + lnPrint("vAxis: { title: '# calls', viewWindowMode: 'pretty', gridlines: { count: -1 } }"); + up(); + lnPrint("};"); + + lnPrint("function selectHandler(category) {"); + down(); + lnPrint("return function() {"); + down(); + printf("var selection = %s[category].getSelection();", tableVar); + lnPrint("if (selection.length < 1) return;"); + lnPrint("var item = selection[0];"); + lnPrintf("var loc = %s[category].getValue(item.row, 0);", dataVar); + lnPrintf("var func = %s[category].getValue(item.row, 1);", dataVar); + lnPrint("var key = loc + '#' + func;"); + lnPrint("var histData = histogramData[category][key];"); + lnPrint("var fnOptions = JSON.parse(JSON.stringify(options));"); + lnPrint("fnOptions.title = loc + ' - ' + func;"); + lnPrint("var chartDiv = document.getElementById(category+'-chart');"); + lnPrint("var chart = new google.visualization.Histogram(chartDiv);"); + lnPrint("var histogramDiv = document.getElementById(category+'-histogram');"); + lnPrint("histogramDiv.style.display = 'block';"); + lnPrint("chart.draw(histData, fnOptions);"); + up(); + lnPrint("}"); + up(); + lnPrint("};"); + lnClose(); // script + } + + private void printHistogramData() { + lnPrint("histogramData = {"); + down(); + printHistogramData(stats.getBuiltinFunctionTasks(), "builtin"); + printHistogramData(stats.getUserFunctionTasks(), "user"); + up(); + lnPrint("}"); + } + + private void printHistogramData(ListMultimap<String, Task> tasks, String category) { + lnPrintf("'%s': {", category); + down(); + for (String function : tasks.keySet()) { + lnPrintf("'%s': google.visualization.arrayToDataTable(", function); + lnPrint("[['duration']"); + for (Task task : tasks.get(function)) { + printf(",[%f]", task.duration / 1000000.); + } + lnPrint("], false),"); + } + up(); + lnPrint("},"); + } + + private void printStatsJs( + List<TasksStatistics> statsList, + String category, + String dataVar, + String tableVar, + long totalNanos) { + String tmpVar = category + dataVar; + lnPrintf("var statsDiv = document.getElementById('%s_function_stats');", category); + if (statsList.isEmpty()) { + lnPrint( + "statsDiv.innerHTML = '<i>No relevant function calls to display. Some minor" + + " builtin functions may have been ignored because their names could not be used" + + " as variables in JavaScript.</i>'"); + } else { + lnPrintf("var %s = new google.visualization.DataTable();", tmpVar); + lnPrintf("%s.addColumn('string', 'Location');", tmpVar); + lnPrintf("%s.addColumn('string', 'Function');", tmpVar); + lnPrintf("%s.addColumn('number', 'count');", tmpVar); + lnPrintf("%s.addColumn('number', 'min (ms)');", tmpVar); + lnPrintf("%s.addColumn('number', 'mean (ms)');", tmpVar); + lnPrintf("%s.addColumn('number', 'median (ms)');", tmpVar); + lnPrintf("%s.addColumn('number', 'max (ms)');", tmpVar); + lnPrintf("%s.addColumn('number', 'std dev (ms)');", tmpVar); + lnPrintf("%s.addColumn('number', 'mean self (ms)');", tmpVar); + lnPrintf("%s.addColumn('number', 'self (ms)');", tmpVar); + lnPrintf("%s.addColumn('number', 'self (%%)');", tmpVar); + lnPrintf("%s.addColumn('number', 'total (ms)');", tmpVar); + lnPrintf("%s.addColumn('number', 'relative (%%)');", tmpVar); + lnPrintf("%s.addRows([", tmpVar); + down(); + for (TasksStatistics stats : statsList) { + double relativeTotal = (double) stats.totalNanos / totalNanos; + double relativeSelf = (double) stats.selfNanos / stats.totalNanos; + String[] split = stats.name.split("#"); + String location = split[0]; + String name = split[1]; + lnPrintf("[{v:'%s', f:'%s'}, ", location, abbreviatePath(location)); + printf("'%s', ", name); + printf("%d, ", stats.count); + printf("%.3f, ", stats.minimumMillis()); + printf("%.3f, ", stats.meanMillis()); + printf("%.3f, ", stats.medianMillis()); + printf("%.3f, ", stats.maximumMillis()); + printf("%.3f, ", stats.standardDeviationMillis); + printf("%.3f, ", stats.selfMeanMillis()); + printf("%.3f, ", stats.selfMillis()); + printf("{v:%.4f, f:'%.3f %%'}, ", relativeSelf, relativeSelf * 100); + printf("%.3f, ", stats.totalMillis()); + printf("{v:%.4f, f:'%.3f %%'}],", relativeTotal, relativeTotal * 100); + } + lnPrint("]);"); + up(); + lnPrintf("%s.%s = %s;", dataVar, category, tmpVar); + lnPrintf("%s.%s = new google.visualization.Table(statsDiv);", tableVar, category); + lnPrintf( + "google.visualization.events.addListener(%s.%s, 'select', selectHandler('%s'));", + tableVar, + category, + category); + lnPrintf( + "%s.%s.draw(%s.%s, {showRowNumber: true, width: '100%%', height: '100%%'});", + tableVar, + category, + dataVar, + category); + } + } + + /** + * Prints two sections for histograms and tables of statistics for user-defined and built-in + * Skylark functions. + */ + void printHtmlBody() { + lnPrint("<a name='skylark_stats'/>"); + lnElement("h3", "Skylark Statistics"); + lnElement("h4", "User-Defined function execution time"); + lnOpen("div", "class", "skylark-histogram", "id", "user-histogram"); + lnElement("div", "class", "skylark-chart", "id", "user-chart"); + lnElement("button", "id", "user-close", "Hide histogram"); + lnClose(); // div user-histogram + lnElement("div", "class", "skylark-table", "id", "user_function_stats"); + + lnElement("h4", "Builtin function execution time"); + lnOpen("div", "class", "skylark-histogram", "id", "builtin-histogram"); + lnElement("div", "class", "skylark-chart", "id", "builtin-chart"); + lnElement("button", "id", "builtin-close", "Hide histogram"); + lnClose(); // div builtin-histogram + lnElement("div", "class", "skylark-table", "id", "builtin_function_stats"); + } + + /** + * Computes a string keeping the structure of the input but reducing the amount of characters on + * elements at the front if necessary. + * + * <p>Reduces the length of function location strings by keeping at least the last element fully + * intact and at most {@link #NUM_LOCATION_CHARS_UNABBREVIATED} from other + * elements from the end. Elements before are abbreviated with their first two characters. + * + * <p>Example: + * "//source/tree/with/very/descriptive/and/long/hierarchy/of/directories/longfilename.bzl:42" + * becomes: "//so/tr/wi/ve/de/an/lo/hierarch/of/directories/longfilename.bzl:42" + * + * <p>There is no fixed length to the result as the last element is kept and the location may + * have many elements. + * + * @param location Either a sequence of path elements separated by + * {@link StandardSystemProperty#FILE_SEPARATOR} and preceded by some root element + * (e.g. "/", "C:\") or path elements separated by "." and having no root element. + */ + private String abbreviatePath(String location) { + String[] elements; + int lowestAbbreviateIndex; + String root; + String separator = StandardSystemProperty.FILE_SEPARATOR.value(); + if (location.contains(separator)) { + elements = location.split(separator); + // must take care to preserve file system roots (e.g. "/", "C:\"), keep separate + lowestAbbreviateIndex = 1; + root = location.substring(0, location.indexOf(separator) + 1); + } else { + // must be java class name for a builtin function + elements = location.split("\\."); + lowestAbbreviateIndex = 0; + root = ""; + separator = "."; + } + + String last = elements[elements.length - 1]; + int remaining = NUM_LOCATION_CHARS_UNABBREVIATED - last.length(); + // start from the next to last element of the location and add until "remaining" many + // chars added, abbreviate rest with first 2 characters + for (int index = elements.length - 2; index >= lowestAbbreviateIndex; index--) { + String element = elements[index]; + if (remaining > 0) { + int length = Math.min(remaining, element.length()); + element = element.substring(0, length); + remaining -= length; + } else { + element = element.substring(0, Math.min(2, element.length())); + } + elements[index] = element; + } + return root + Joiner.on(separator).join(Arrays.asList(elements).subList(1, elements.length)); + } +} + + diff --git a/src/main/java/com/google/devtools/build/lib/profiler/output/TextPrinter.java b/src/main/java/com/google/devtools/build/lib/profiler/output/TextPrinter.java new file mode 100644 index 0000000000..5b6413e88d --- /dev/null +++ b/src/main/java/com/google/devtools/build/lib/profiler/output/TextPrinter.java @@ -0,0 +1,111 @@ +// Copyright 2015 Google Inc. All rights reserved. +// +// Licensed under the Apache License, Version 2.0 (the "License"); +// you may not use this file except in compliance with the License. +// You may obtain a copy of the License at +// +// http://www.apache.org/licenses/LICENSE-2.0 +// +// Unless required by applicable law or agreed to in writing, software +// distributed under the License is distributed on an "AS IS" BASIS, +// WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. +// See the License for the specific language governing permissions and +// limitations under the License. +package com.google.devtools.build.lib.profiler.output; + +import com.google.common.base.Preconditions; + +import java.io.PrintStream; + +/** + * Utility function for writing text data to a {@link PrintStream}. + */ +public abstract class TextPrinter { + + protected static final String TWO_COLUMN_FORMAT = "%-37s %10s"; + protected static final String THREE_COLUMN_FORMAT = "%-28s %10s %8s"; + + private static final String INDENT = " "; + protected final PrintStream out; + private StringBuffer indent; + + protected TextPrinter(PrintStream out) { + this.out = out; + this.indent = new StringBuffer(); + } + + /** + * Increase indentation level + */ + protected void down() { + indent.append(INDENT); + } + + /** + * Decrease indentation level + */ + protected void up() { + Preconditions.checkState( + indent.length() >= INDENT.length(), + "Cannot reduce indentation level, this/a previous call to up() is not matched by down()."); + indent.setLength(indent.length() - INDENT.length()); + } + + protected void print(Object text) { + out.print(text); + } + + protected void printLn() { + out.println(); + } + + /** + * newline and indent by current indentation level + */ + protected void lnIndent() { + printLn(); + out.print(indent); + } + + /** + * newline, indent and print the Object + * @see PrintStream#print(Object) + */ + protected void lnPrint(Object text) { + lnIndent(); + out.print(text); + } + + /** + * print text and a newline + */ + protected void printLn(String text) { + out.print(text); + printLn(); + } + + /** + * newline, indent and print the formatted text + */ + protected void lnPrintf(String format, Object... args) { + lnIndent(); + out.printf(format, args); + } + + protected void printf(String format, Object... args) { + out.printf(format, args); + } + + /** + * Represents a double value as either "N/A" if it is NaN, or as a percentage with "%.2f%%". + * @param relativeValue is assumed to be a ratio of two values and will be multiplied with 100 + * for output + */ + public static String prettyPercentage(double relativeValue) { + if (Double.isNaN(relativeValue)) { + return "N/A"; + } + return String.format("%.2f%%", relativeValue * 100); + } +} + 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<Pair<String, Double>> { + + private static final EnumSet<ProfilerTask> 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<ProfilerTask> DEFAULT_FILTER = + EnumSet.of(ProfilerTask.ACTION_LOCK, ProfilerTask.WAIT); + + private static final List<Pair<String, EnumSet<ProfilerTask>>> FILTERS = + Arrays.asList( + Pair.of("the builder overhead", EnumSet.allOf(ProfilerTask.class)), + Pair.of( + "the VFS calls", + ProfilerTask.allSatisfying( + new Predicate<ProfilerTask>() { + @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<Long> 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<Pair<String, Double>> iterator() { + return new Iterator<Pair<String, Double>>() { + + Iterator<Long> durations = criticalPathDurations.iterator(); + Iterator<Pair<String, EnumSet<ProfilerTask>>> filters = FILTERS.iterator(); + boolean overheadFilter = true; + + @Override + public boolean hasNext() { + return durations.hasNext(); + } + + @Override + public Pair<String, Double> 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<Long> getCriticalPathDurations(ProfileInfo info) { + List<Long> list = new ArrayList<>(FILTERS.size()); + + for (Pair<String, EnumSet<ProfilerTask>> 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<String, EnumSet<ProfilerTask>> typeFilter( + String description, ProfilerTask... tasks) { + EnumSet<ProfilerTask> 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<ProfilerTask> { + + private final ProfilePhase phase; + private final long phaseDurationNanos; + private final long totalDurationNanos; + private final EnumMap<ProfilerTask, AggregateAttr> 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<Task> 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<ProfilerTask> iterator() { + return Iterators.filter( + aggregateTaskStatistics.keySet().iterator(), + new Predicate<ProfilerTask>() { + @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<ProfilePhase> { + + private final long totalDurationNanos; + private final EnumMap<ProfilePhase, Long> 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<ProfilePhase> 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<ProfilerTask> { + + /** + * Pair of duration and count for sorting by duration first and count in case of tie + */ + public static class Stat implements Comparable<Stat> { + 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<ProfilerTask, TreeMultimap<Stat, String>> 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<Entry<Stat, String>> getSortedStatistics(ProfilerTask taskType) { + return sortedStatistics.get(taskType).entries(); + } + + public int getStatisticsCount(ProfilerTask taskType) { + return sortedStatistics.get(taskType).size(); + } + + @Override + public Iterator<ProfilerTask> iterator() { + return sortedStatistics.keySet().iterator(); + } + + /** + * Group into VFS operations and build maps from path to duration. + */ + private void collectVfsEntries(List<Task> taskList) { + EnumMap<ProfilerTask, Map<String, Stat>> stats = Maps.newEnumMap(ProfilerTask.class); + for (Task task : taskList) { + collectVfsEntries(Arrays.asList(task.subtasks)); + if (!task.type.name().startsWith("VFS_")) { + continue; + } + + Map<String, Stat> 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<String, Stat> statsForType = stats.get(type); + TreeMultimap<Stat, String> 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<String, Task> userFunctionTasks; + private final ListMultimap<String, Task> builtinFunctionTasks; + private final List<TasksStatistics> userFunctionStats; + private final List<TasksStatistics> 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<String, Task> 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<String, Task> getBuiltinFunctionTasks() { + return builtinFunctionTasks; + } + + public List<TasksStatistics> getBuiltinFunctionStats() { + return builtinFunctionStats; + } + + public List<TasksStatistics> 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<String, Task> tasks, List<TasksStatistics> stats) { + long total = 0L; + for (Entry<String, List<Task>> 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/chart/TasksStatistics.java b/src/main/java/com/google/devtools/build/lib/profiler/statistics/TasksStatistics.java index 0731118a08..0e7ea71bf0 100644 --- a/src/main/java/com/google/devtools/build/lib/profiler/chart/TasksStatistics.java +++ b/src/main/java/com/google/devtools/build/lib/profiler/statistics/TasksStatistics.java @@ -11,7 +11,7 @@ // 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; +package com.google.devtools.build.lib.profiler.statistics; import com.google.devtools.build.lib.profiler.ProfileInfo.Task; @@ -22,7 +22,7 @@ import java.util.List; /** * Data container to aggregate execution time statistics of multiple tasks grouped by some name. */ -class TasksStatistics { +public class TasksStatistics { public final String name; public final int count; public final long minNanos; 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<String, String> currentPathMapping = Functions.<String>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<String, String>() { - @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<ProfilePhase, PhaseStatistics> 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<ProfilePhaseStatistics> 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<ProfilePhaseStatistics> getStatistics( - CommandEnvironment env, ProfileInfo info, ProfileOptions opts) { - try { - ProfileInfo.aggregateProfile(info, getInfoListener(env)); - env.getReporter().handle(Event.info("Analyzing relationships")); - - info.analyzeRelationships(); - - List<ProfilePhaseStatistics> 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<ProfileInfo.Task> 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<Stat> { - 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<ProfileInfo.Task> taskList = info.getTasksForPhase(phaseTask); - EnumMap<ProfilerTask, Map<String, Stat>> 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<String, Stat> statsForType = stats.get(type); - TreeMultimap<Stat, String> sortedStats = - TreeMultimap.create(Ordering.natural().reverse(), Ordering.natural()); - - Multimaps.invertFrom(Multimaps.forMap(statsForType), sortedStats); - - int numPrinted = 0; - for (Map.Entry<Stat, String> 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<ProfilerTask, Map<String, Stat>> stats, - List<ProfileInfo.Task> taskList) { - for (ProfileInfo.Task task : taskList) { - collectVfsEntries(stats, Arrays.asList(task.subtasks)); - if (!task.type.name().startsWith("VFS_")) { - continue; - } - - Map<String, Stat> 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<ProfilerTask> getTypeFilter(ProfilerTask... tasks) { - EnumSet<ProfilerTask> 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<ProfileInfo.Task> 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<ProfilerTask> 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<ProfilerTask> 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", diff --git a/src/test/java/BUILD b/src/test/java/BUILD index da59f464ac..64148e6e25 100644 --- a/src/test/java/BUILD +++ b/src/test/java/BUILD @@ -18,10 +18,14 @@ java_library( "//src/main/java:actions", "//src/main/java:analysis-exec-rules-skyframe", "//src/main/java:bazel-core", + "//src/main/java:clock", "//src/main/java:collect", "//src/main/java:concurrent", "//src/main/java:events", + "//src/main/java:io", + "//src/main/java:os_util", "//src/main/java:packages", + "//src/main/java:util", "//src/main/java:vfs", "//third_party:guava", "//third_party:guava-testlib", @@ -44,6 +48,7 @@ java_test( "//src/main/java:concurrent", "//src/main/java:events", "//src/main/java:skyframe-base", + "//src/main/java:util", "//src/main/java:vfs", "//third_party:guava", "//third_party:guava-testlib", @@ -82,10 +87,13 @@ java_library( deps = [ ":testutil", "//src/main/java:bazel-core", + "//src/main/java:clock", "//src/main/java:concurrent", "//src/main/java:events", + "//src/main/java:io", "//src/main/java:packages", "//src/main/java:shell", + "//src/main/java:util", "//src/main/java:vfs", "//third_party:guava", "//third_party:guava-testlib", @@ -138,14 +146,19 @@ java_test( ":foundations_testutil", ":test_runner", ":testutil", + "//src/main/java:base-util", "//src/main/java:bazel-core", + "//src/main/java:clock", "//src/main/java:collect", "//src/main/java:concurrent", "//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", "//third_party:guava", "//third_party:guava-testlib", @@ -170,7 +183,9 @@ java_test( ":test_runner", ":testutil", "//src/main/java:bazel-core", + "//src/main/java:clock", "//src/main/java:options", + "//src/main/java:util", "//src/main/java:vfs", "//third_party:guava", "//third_party:guava-testlib", @@ -191,11 +206,14 @@ java_library( "//src/main/java:actions", "//src/main/java:analysis-exec-rules-skyframe", "//src/main/java:bazel-core", + "//src/main/java:clock", "//src/main/java:concurrent", "//src/main/java:events", + "//src/main/java:io", "//src/main/java:options", "//src/main/java:packages", "//src/main/java:skyframe-base", + "//src/main/java:util", "//src/main/java:vfs", "//third_party:guava", "//third_party:guava-testlib", @@ -220,11 +238,13 @@ java_test( "//src/main/java:actions", "//src/main/java:analysis-exec-rules-skyframe", "//src/main/java:bazel-core", + "//src/main/java:clock", "//src/main/java:collect", "//src/main/java:concurrent", "//src/main/java:events", "//src/main/java:options", "//src/main/java:packages", + "//src/main/java:util", "//src/main/java:vfs", "//third_party:guava", "//third_party:guava-testlib", @@ -256,13 +276,16 @@ java_library( "//src/main/java:analysis-exec-rules-skyframe", "//src/main/java:bazel-core", "//src/main/java:buildtool-runtime", + "//src/main/java:clock", "//src/main/java:collect", "//src/main/java:concurrent", "//src/main/java:events", + "//src/main/java:io", "//src/main/java:options", "//src/main/java:packages", "//src/main/java:runtime", "//src/main/java:skyframe-base", + "//src/main/java:util", "//src/main/java:vfs", "//src/main/protobuf:proto_extra_actions_base", "//third_party:guava", @@ -290,6 +313,7 @@ java_test( "//src/main/java:actions", "//src/main/java:analysis-exec-rules-skyframe", "//src/main/java:bazel-core", + "//src/main/java:io", "//src/main/java:vfs", "//src/main/protobuf:proto_extra_actions_base", "//third_party:guava", @@ -318,6 +342,7 @@ java_test( "//src/main/java:bazel-core", "//src/main/java:options", "//src/main/java:packages", + "//src/main/java:util", "//src/main/java:vfs", "//src/main/protobuf:proto_extra_actions_base", "//third_party:guava", @@ -345,6 +370,7 @@ java_test( "//src/main/java:analysis-exec-rules-skyframe", "//src/main/java:bazel-core", "//src/main/java:packages", + "//src/main/java:util", "//src/main/java:vfs", "//third_party:guava", "//third_party:junit4", @@ -415,10 +441,13 @@ java_library( ":testutil", "//src/main/java:analysis-exec-rules-skyframe", "//src/main/java:bazel-core", + "//src/main/java:clock", "//src/main/java:events", + "//src/main/java:io", "//src/main/java:options", "//src/main/java:packages", "//src/main/java:skyframe-base", + "//src/main/java:util", "//src/main/java:vfs", "//src/main/protobuf:proto_extra_actions_base", "//third_party:guava", @@ -446,6 +475,7 @@ java_test( "//src/main/java:bazel-core", "//src/main/java:events", "//src/main/java:packages", + "//src/main/java:util", "//src/main/java:vfs", "//third_party:guava", "//third_party:guava-testlib", @@ -515,6 +545,7 @@ java_test( "//src/main/java:concurrent", "//src/main/java:events", "//src/main/java:packages", + "//src/main/java:util", "//src/main/java:vfs", "//third_party:guava", "//third_party:guava-testlib", @@ -551,6 +582,7 @@ java_test( ":testutil", "//src/main/java:analysis-exec-rules-skyframe", "//src/main/java:bazel-core", + "//src/main/java:util", "//src/main/java:vfs", "//third_party:guava", "//third_party:guava-testlib", @@ -592,9 +624,12 @@ java_test( ":testutil", "//src/main/java:actions", "//src/main/java:analysis-exec-rules-skyframe", + "//src/main/java:clock", "//src/main/java:events", "//src/main/java:options", + "//src/main/java:os_util", "//src/main/java:shell", + "//src/main/java:util", "//src/main/java:vfs", "//src/main/java/com/google/devtools/build/lib/sandbox", "//third_party:guava", |