Add --task_tree and --task_tree_threshold options.

Options allow displaying some tasks in more detail, e.g. for inspecting what
exactly a Skylark user-defined function calls and how long that takes.

--
MOS_MIGRATED_REVID=104505599

8 files changed, 215 insertions, 45 deletions

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 f7ec6db708..b93b8d99dd 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
@@ -18,10 +18,14 @@ import static com.google.devtools.build.lib.profiler.ProfilerTask.TASK_COUNT;
 
 import com.google.common.base.Joiner;
 import com.google.common.base.Preconditions;
+import com.google.common.base.Predicate;
+import com.google.common.collect.ImmutableList;
+import com.google.common.collect.Iterables;
 import com.google.common.collect.ListMultimap;
 import com.google.common.collect.Lists;
 import com.google.common.collect.Maps;
 import com.google.common.collect.MultimapBuilder.ListMultimapBuilder;
+import com.google.common.collect.Ordering;
 import com.google.common.collect.Sets;
 import com.google.devtools.build.lib.util.VarInt;
 import com.google.devtools.build.lib.vfs.Path;
@@ -29,6 +33,7 @@ import com.google.devtools.build.lib.vfs.Path;
 import java.io.BufferedInputStream;
 import java.io.DataInputStream;
 import java.io.IOException;
+import java.io.PrintStream;
 import java.io.UnsupportedEncodingException;
 import java.nio.ByteBuffer;
 import java.util.ArrayDeque;
@@ -42,6 +47,8 @@ import java.util.HashSet;
 import java.util.List;
 import java.util.Map;
 import java.util.Set;
+import java.util.concurrent.TimeUnit;
+import java.util.regex.Pattern;
 import java.util.zip.Inflater;
 import java.util.zip.InflaterInputStream;
 
@@ -153,6 +160,14 @@ public class ProfileInfo {
     }
   }
 
+  public static final Ordering<Task> TASK_DURATION_ORDERING =
+      new Ordering<Task>() {
+        @Override
+        public int compare(Task o1, Task o2) {
+          return Long.compare(o1.durationNanos, o2.durationNanos);
+        }
+      };
+
   /**
    * Container for the profile record information.
    *
@@ -164,7 +179,7 @@ public class ProfileInfo {
     public final int id;
     public final int parentId;
     public final long startTime;
-    public final long duration;
+    public final long durationNanos;
     public final ProfilerTask type;
     final CompactStatistics stats;
     // Contains statistic for a task and all subtasks. Populated only for root tasks.
@@ -176,13 +191,20 @@ public class ProfileInfo {
     // Reference to the related task (e.g. ACTION_GRAPH->ACTION task relation).
     private Task relatedTask;
 
-    Task(long threadId, int id, int parentId, long startTime, long duration,
-         ProfilerTask type, int descIndex, CompactStatistics stats) {
+    Task(
+        long threadId,
+        int id,
+        int parentId,
+        long startTime,
+        long durationNanos,
+        ProfilerTask type,
+        int descIndex,
+        CompactStatistics stats) {
       this.threadId = threadId;
       this.id = id;
       this.parentId = parentId;
       this.startTime = startTime;
-      this.duration = duration;
+      this.durationNanos = durationNanos;
       this.type = type;
       this.descIndex = descIndex;
       this.stats = stats;
@@ -258,6 +280,77 @@ public class ProfileInfo {
     }
 
     /**
+     * Produce a nicely indented tree of the task and its subtasks with execution time.
+     *
+     * <p>Execution times are in milliseconds.
+     *
+     * <p>Example:
+     *
+     * <pre>
+     * 636779 SKYLARK_USER_FN (259.593 ms) /path/file.bzl:42#function [
+     *   636810 SKYLARK_USER_FN (257.768 ms) /path/file.bzl:133#_other_function [
+     *     636974 SKYLARK_BUILTIN_FN (254.596 ms) some.package.PackageFactory$9#genrule []
+     *   2 subtree(s) omitted]
+     * ]
+     * </pre>
+     *
+     * @param durationThresholdMillis Tasks with a shorter duration than this threshold will be
+     *  skipped
+     * @return whether this task took longer than the threshold and was thus printed
+     */
+    public boolean printTaskTree(PrintStream out, long durationThresholdMillis) {
+      return printTaskTree(out, "", TimeUnit.MILLISECONDS.toNanos(durationThresholdMillis));
+    }
+
+    /**
+     * @see #printTaskTree(PrintStream, long)
+     */
+    private boolean printTaskTree(
+        PrintStream out, String indent, final long durationThresholdNanos) {
+      if (durationNanos < durationThresholdNanos) {
+        return false;
+      }
+      out.printf("%s%6d %s", indent, id, type);
+      out.printf(" (%5.3f ms) ", durationNanos / 1000000.0);
+      out.print(getDescription());
+
+      out.print(" [");
+      ImmutableList<Task> sortedSubTasks =
+          TASK_DURATION_ORDERING
+              .reverse()
+              .immutableSortedCopy(
+                  Iterables.filter(
+                      Arrays.asList(subtasks),
+                      new Predicate<Task>() {
+                        @Override
+                        public boolean apply(Task task) {
+                          return task.durationNanos >= durationThresholdNanos;
+                        }
+                      }));
+      String sep = "";
+      for (Task task : sortedSubTasks) {
+        out.print(sep);
+        out.println();
+        task.printTaskTree(out, indent + "  ", durationThresholdNanos);
+        sep = ",";
+      }
+      if (!sortedSubTasks.isEmpty()) {
+        out.println();
+        out.print(indent);
+      }
+      int skipped = subtasks.length - sortedSubTasks.size();
+      if (skipped > 0) {
+        out.printf("%d subtree(s) omitted", skipped);
+      }
+      out.print("]");
+
+      if (indent.equals("")) {
+        out.println();
+      }
+      return true;
+    }
+
+    /**
      * Tasks records by default sorted by their id. Since id was obtained using
      * AtomicInteger, this comparison will correctly sort tasks in time-ascending
      * order regardless of their origin thread.
@@ -513,7 +606,7 @@ public class ProfileInfo {
       totalTime += attr.totalTime;
       if (task.type == type) {
         count++;
-        totalTime += (task.duration - task.getInheritedDuration());
+        totalTime += (task.durationNanos - task.getInheritedDuration());
       }
     }
     return new AggregateAttr(count, totalTime);
@@ -569,7 +662,7 @@ public class ProfileInfo {
       duration = phaseTask.relatedTask.startTime - phaseTask.startTime;
     } else {
       Task lastTask = rootTasksById.get(rootTasksById.size() - 1);
-      duration = lastTask.startTime + lastTask.duration - phaseTask.startTime;
+      duration = lastTask.startTime + lastTask.durationNanos - phaseTask.startTime;
     }
     Preconditions.checkState(duration >= 0);
     return duration;
@@ -705,7 +798,7 @@ public class ProfileInfo {
           }
         }
         if (actionTask.type == ProfilerTask.ACTION) {
-          long duration = actionTask.duration;
+          long duration = actionTask.durationNanos;
           if (ignoredTasks.contains(actionTask)) {
             duration = 0L;
           } else {
@@ -734,7 +827,7 @@ public class ProfileInfo {
       if (task.type == CRITICAL_PATH) {
         CriticalPathEntry entry = null;
         for (Task shared : task.subtasks) {
-          entry = new CriticalPathEntry(shared, shared.duration, entry);
+          entry = new CriticalPathEntry(shared, shared.durationNanos, entry);
         }
         return entry;
       }
@@ -825,7 +918,7 @@ public class ProfileInfo {
     Task related = parallelBuilderCompletionQueueTasks.get(actionTask);
     if (related != null) {
       Preconditions.checkState(related.type == ProfilerTask.ACTION_BUILDER);
-      long time = related.startTime - (actionTask.startTime + actionTask.duration);
+      long time = related.startTime - (actionTask.startTime + actionTask.durationNanos);
       Preconditions.checkState(time >= 0);
       return time;
     } else {
@@ -834,6 +927,23 @@ public class ProfileInfo {
   }
 
   /**
+   * Searches for the task by its description. Linear in the number of tasks.
+   * @param description a regular expression pattern which will be matched against the task
+   * description
+   * @return an Iterable of Tasks matching the description
+   */
+  public Iterable<Task> findTasksByDescription(final Pattern description) {
+    return Iterables.filter(
+        allTasksById,
+        new Predicate<Task>() {
+          @Override
+          public boolean apply(Task task) {
+            return description.matcher(task.getDescription()).find();
+          }
+        });
+  }
+
+  /**
    * Returns an empty array used to store task statistics. Array index
    * corresponds to the ProfilerTask ordinal() value associated with the
    * given statistic. Absent statistics are stored as null.
diff --git a/src/main/java/com/google/devtools/build/lib/profiler/chart/AggregatingChartCreator.java b/src/main/java/com/google/devtools/build/lib/profiler/chart/AggregatingChartCreator.java
index a3f29c753f..98c58cd507 100644
--- a/src/main/java/com/google/devtools/build/lib/profiler/chart/AggregatingChartCreator.java
+++ b/src/main/java/com/google/devtools/build/lib/profiler/chart/AggregatingChartCreator.java
@@ -128,7 +128,7 @@ public class AggregatingChartCreator implements ChartCreator {
    */
   private void createBar(Chart chart, Task task, ChartBarType type) {
     String label = task.type.description + ": " + task.getDescription();
-    chart.addBar(task.threadId, task.startTime, task.startTime + task.duration, type, label);
+    chart.addBar(task.threadId, task.startTime, task.startTime + task.durationNanos, type, label);
   }
 
   /**
diff --git a/src/main/java/com/google/devtools/build/lib/profiler/chart/DetailedChartCreator.java b/src/main/java/com/google/devtools/build/lib/profiler/chart/DetailedChartCreator.java
index 4ee2f19524..2477d3a9a6 100644
--- a/src/main/java/com/google/devtools/build/lib/profiler/chart/DetailedChartCreator.java
+++ b/src/main/java/com/google/devtools/build/lib/profiler/chart/DetailedChartCreator.java
@@ -53,7 +53,7 @@ public class DetailedChartCreator implements ChartCreator {
     for (Task task : info.allTasksById) {
       String label = task.type.description + ": " + task.getDescription();
       ChartBarType type = chart.lookUpType(task.type.description);
-      long stop = task.startTime + task.duration;
+      long stop = task.startTime + task.durationNanos;
       CriticalPathEntry entry = null;
 
       // for top level tasks, check if they are on the critical path
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
index 0e4dc6e6d7..b2768bde80 100644
--- 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
@@ -142,7 +142,7 @@ public final class SkylarkHtml extends HtmlPrinter {
       lnPrintf("'%s': google.visualization.arrayToDataTable(", function);
       lnPrint("[['duration']");
       for (Task task : tasks.get(function)) {
-        printf(",[%f]", task.duration / 1000000.);
+        printf(",[%f]", task.durationNanos / 1000000.);
       }
       lnPrint("], false),");
     }
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
index 7ef69c7e49..3f6e326adf 100644
--- 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
@@ -54,7 +54,7 @@ public final class PhaseStatistics implements Iterable<ProfilerTask> {
       for (Task task : taskList) {
         // Tasks on the phaseTask thread already accounted for in the phaseDuration.
         if (task.threadId != phaseTask.threadId) {
-          duration += task.duration;
+          duration += task.durationNanos;
         }
       }
       totalDurationNanos = duration;
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
index 27856fc31b..4c52c47eb5 100644
--- 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
@@ -111,7 +111,7 @@ public final class PhaseVfsStatistics implements Iterable<ProfilerTask> {
         stat = new Stat();
       }
 
-      stat.duration += task.duration;
+      stat.duration += task.durationNanos;
       stat.count++;
       statsForType.put(path, stat);
     }
diff --git a/src/main/java/com/google/devtools/build/lib/profiler/statistics/TasksStatistics.java b/src/main/java/com/google/devtools/build/lib/profiler/statistics/TasksStatistics.java
index 1a422db914..72afab45bf 100644
--- a/src/main/java/com/google/devtools/build/lib/profiler/statistics/TasksStatistics.java
+++ b/src/main/java/com/google/devtools/build/lib/profiler/statistics/TasksStatistics.java
@@ -13,10 +13,9 @@
 // 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.ProfileInfo.Task;
 
-import java.util.Collections;
-import java.util.Comparator;
 import java.util.List;
 
 /**
@@ -91,28 +90,19 @@ public class TasksStatistics {
   }
 
   /**
-   * @param name
-   * @param tasks
    * @return The set of statistics grouped in this class, computed from a list of {@link Task}s.
    */
   public static TasksStatistics create(String name, List<Task> tasks) {
-    Collections.sort(
-        tasks,
-        new Comparator<Task>() {
-          @Override
-          public int compare(Task o1, Task o2) {
-            return Long.compare(o1.duration, o2.duration);
-          }
-        });
+    tasks = ProfileInfo.TASK_DURATION_ORDERING.immutableSortedCopy(tasks);
     int count = tasks.size();
-    long min = tasks.get(0).duration;
-    long max = tasks.get(count - 1).duration;
+    long min = tasks.get(0).durationNanos;
+    long max = tasks.get(count - 1).durationNanos;
 
     int midIndex = count / 2;
     double median =
         tasks.size() % 2 == 0
-            ? (tasks.get(midIndex).duration + tasks.get(midIndex - 1).duration) / 2.0
-            : tasks.get(midIndex).duration;
+            ? (tasks.get(midIndex).durationNanos + tasks.get(midIndex - 1).durationNanos) / 2.0
+            : tasks.get(midIndex).durationNanos;
 
     // Compute standard deviation with a shift to avoid catastrophic cancellation
     // and also do it in milliseconds, as in nanoseconds it overflows
@@ -122,9 +112,9 @@ public class TasksStatistics {
     final long shift = min;
 
     for (Task task : tasks) {
-      sum += task.duration;
-      self += task.duration - task.getInheritedDuration();
-      double taskDurationShiftMillis = toMilliSeconds(task.duration - shift);
+      sum += task.durationNanos;
+      self += task.durationNanos - task.getInheritedDuration();
+      double taskDurationShiftMillis = toMilliSeconds(task.durationNanos - shift);
       sumOfSquaredShiftedMillis += taskDurationShiftMillis * taskDurationShiftMillis;
     }
     double sumShiftedMillis = toMilliSeconds(sum - count * shift);
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 0d728cacc2..1a21b9ca0f 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,10 +13,13 @@
 // limitations under the License.
 package com.google.devtools.build.lib.runtime.commands;
 
+import com.google.common.base.Joiner;
+import com.google.common.collect.Iterables;
 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.InfoListener;
+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.profiler.output.HtmlCreator;
@@ -41,6 +44,7 @@ import com.google.devtools.common.options.OptionsProvider;
 import java.io.IOException;
 import java.io.PrintStream;
 import java.util.EnumMap;
+import java.util.regex.Pattern;
 
 /**
  * Command line wrapper for analyzing Blaze build profiles.
@@ -92,6 +96,24 @@ public final class ProfileCommand implements BlazeCommand {
     )
     public boolean htmlDetails;
 
+    @Option(
+      name = "task_tree",
+      defaultValue = "null",
+      converter = Converters.RegexPatternConverter.class,
+      help =
+          "Print the tree of profiler tasks from all tasks matching the given regular expression."
+    )
+    public Pattern taskTree;
+
+    @Option(
+      name = "task_tree_threshold",
+      defaultValue = "50",
+      help =
+          "When printing a task tree, will skip tasks with a duration that is less than the"
+              + " given threshold in milliseconds."
+    )
+    public long taskTreeThreshold;
+
     @Option(name = "vfs_stats",
         defaultValue = "false",
         help = "If present, include VFS path statistics.")
@@ -132,8 +154,7 @@ public final class ProfileCommand implements BlazeCommand {
       opts.vfsStatsLimit = 0;
     }
 
-    PrintStream out = new PrintStream(env.getReporter().getOutErr().getOutputStream());
-    try {
+    try (PrintStream out = new PrintStream(env.getReporter().getOutErr().getOutputStream())) {
       env.getReporter().handle(Event.warn(
           null, "This information is intended for consumption by Blaze developers"
               + " only, and may change at any time.  Script against it at your own risk"));
@@ -145,6 +166,11 @@ public final class ProfileCommand implements BlazeCommand {
               profileFile, getInfoListener(env));
           ProfileInfo.aggregateProfile(info, getInfoListener(env));
 
+          if (opts.taskTree != null) {
+            printTaskTree(out, name, info, opts.taskTree, opts.taskTreeThreshold);
+            continue;
+          }
+
           PhaseSummaryStatistics phaseSummaryStatistics = new PhaseSummaryStatistics(info);
           EnumMap<ProfilePhase, PhaseStatistics> phaseStatistics =
               new EnumMap<>(ProfilePhase.class);
@@ -185,12 +211,38 @@ public final class ProfileCommand implements BlazeCommand {
               null, "Failed to process file " + name + ": " + e.getMessage()));
         }
       }
-    } finally {
-      out.flush();
     }
     return ExitCode.SUCCESS;
   }
 
+  /**
+   * Prints trees rooted at tasks with a description matching a pattern.
+   * @see Task#printTaskTree(PrintStream, long)
+   */
+  private void printTaskTree(
+      PrintStream out,
+      String fileName,
+      ProfileInfo info,
+      Pattern taskPattern,
+      long taskDurationThreshold) {
+    Iterable<Task> tasks = info.findTasksByDescription(taskPattern);
+    if (Iterables.isEmpty(tasks)) {
+      out.printf("No tasks matching %s found in profile file %s.", taskPattern, fileName);
+      out.println();
+    } else {
+      int skipped = 0;
+      for (Task task : tasks) {
+        if (!task.printTaskTree(out, taskDurationThreshold)) {
+          skipped++;
+        }
+      }
+      if (skipped > 0) {
+        out.printf("Skipped %d matching task(s) below the duration threshold.", skipped);
+      }
+      out.println();
+    }
+  }
+
   private void dumpProfile(
       CommandEnvironment env, ProfileInfo info, PrintStream out, String dumpMode) {
     if (!dumpMode.contains("unsorted")) {
@@ -212,10 +264,22 @@ public final class ProfileCommand implements BlazeCommand {
   }
 
   private void dumpTask(ProfileInfo.Task task, PrintStream out, int indent) {
-    StringBuilder builder = new StringBuilder(String.format(
-        "\n%s %s\nThread: %-6d  Id: %-6d  Parent: %d\nStart time: %-12s   Duration: %s",
-        task.type, task.getDescription(), task.threadId, task.id, task.parentId,
-        TimeUtilities.prettyTime(task.startTime), TimeUtilities.prettyTime(task.duration)));
+    StringBuilder builder =
+        new StringBuilder(
+            String.format(
+                Joiner.on('\n')
+                    .join(
+                        "",
+                        "%s %s",
+                        "Thread: %-6d  Id: %-6d  Parent: %d",
+                        "Start time: %-12s   Duration: %s"),
+                task.type,
+                task.getDescription(),
+                task.threadId,
+                task.id,
+                task.parentId,
+                TimeUtilities.prettyTime(task.startTime),
+                TimeUtilities.prettyTime(task.durationNanos)));
     if (task.hasStats()) {
       builder.append("\n");
       ProfileInfo.AggregateAttr[] stats = task.getStatAttrArray();
@@ -245,9 +309,15 @@ public final class ProfileCommand implements BlazeCommand {
       }
     }
     out.println(
-        task.threadId + "|" + task.id + "|" + task.parentId + "|"
-        + task.startTime + "|" + task.duration + "|"
-        + aggregateString.toString().trim() + "|"
-        + task.type + "|" + task.getDescription());
+        Joiner.on('|')
+            .join(
+                task.threadId,
+                task.id,
+                task.parentId,
+                task.startTime,
+                task.durationNanos,
+                aggregateString.toString().trim(),
+                task.type,
+                task.getDescription()));
   }
 }