Save subtasks for Skylark function profiler tasks and then report self time of function calls in HTML output

--
MOS_MIGRATED_REVID=102663672

4 files changed, 112 insertions, 33 deletions

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
index 9db851699d..866d050498 100644
--- 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
@@ -14,6 +14,8 @@
 
 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;
@@ -21,6 +23,7 @@ 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;
 
@@ -30,6 +33,10 @@ import java.util.Map.Entry;
  */
 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;
@@ -83,10 +90,10 @@ public final class SkylarkStatistics {
   void printHtmlHead() {
     out.println("<style type=\"text/css\"><!--");
     out.println("div.skylark-histogram {");
-    out.println("  width: 95%; height: 220px; margin: 0 auto; display: none;");
+    out.println("  width: 95%; margin: 0 auto; display: none;");
     out.println("}");
     out.println("div.skylark-chart {");
-    out.println("  width: 95%; height: 200px; margin: 0 auto;");
+    out.println("  width: 100%; height: 200px; margin: 0 auto 2em;");
     out.println("}");
     out.println("div.skylark-table {");
     out.println("  width: 95%; margin: 0 auto;");
@@ -189,9 +196,11 @@ public final class SkylarkStatistics {
       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', 'standard deviation (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', 'total (ms)');\n", tmpVar);
-      out.printf("  %s.addColumn('number', 'relative total (%%)');\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;
@@ -199,8 +208,10 @@ public final class SkylarkStatistics {
         String location = split[0];
         String name = split[1];
         out.printf(
-            "    ['%s', '%s', %d, %.4f, %.4f, %.4f, %.4f, %.4f, %.4f, {v:%.4f, f:'%.4f %%'}],\n",
+            "    [{v:'%s', f:'%s'}, '%s', %d, %.3f, %.3f, %.3f, %.3f, %.3f, %.3f, %.3f, %.3f,"
+            + " {v:%.4f, f:'%.3f %%'}],\n",
             location,
+            abbreviatePath(location),
             name,
             stats.count,
             stats.minimumMillis(),
@@ -208,6 +219,8 @@ public final class SkylarkStatistics {
             stats.medianMillis(),
             stats.maximumMillis(),
             stats.standardDeviationMillis,
+            stats.selfMeanMillis(),
+            stats.selfMillis(),
             stats.totalMillis(),
             relativeTotal,
             relativeTotal * 100);
@@ -250,4 +263,59 @@ public final class SkylarkStatistics {
     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/chart/TasksStatistics.java b/src/main/java/com/google/devtools/build/lib/profiler/chart/TasksStatistics.java
index f95b0a28da..0731118a08 100644
--- a/src/main/java/com/google/devtools/build/lib/profiler/chart/TasksStatistics.java
+++ b/src/main/java/com/google/devtools/build/lib/profiler/chart/TasksStatistics.java
@@ -27,32 +27,31 @@ class TasksStatistics {
   public final int count;
   public final long minNanos;
   public final long maxNanos;
-  public final double meanNanos;
   public final double medianNanos;
   /** Standard deviation of the execution time in milliseconds since computation in nanoseconds can
    * overflow.
    */
   public final double standardDeviationMillis;
-
   public final long totalNanos;
+  public final long selfNanos;
 
   public TasksStatistics(
       String name,
       int count,
-      long min,
-      long max,
-      double mean,
-      double median,
-      double standardDeviation,
-      long total) {
+      long minNanos,
+      long maxNanos,
+      double medianNanos,
+      double standardDeviationMillis,
+      long totalNanos,
+      long selfNanos) {
     this.name = name;
     this.count = count;
-    this.minNanos = min;
-    this.maxNanos = max;
-    this.meanNanos = mean;
-    this.medianNanos = median;
-    this.standardDeviationMillis = standardDeviation;
-    this.totalNanos = total;
+    this.minNanos = minNanos;
+    this.maxNanos = maxNanos;
+    this.medianNanos = medianNanos;
+    this.standardDeviationMillis = standardDeviationMillis;
+    this.totalNanos = totalNanos;
+    this.selfNanos = selfNanos;
   }
 
   public double minimumMillis() {
@@ -63,8 +62,12 @@ class TasksStatistics {
     return toMilliSeconds(maxNanos);
   }
 
+  public double meanNanos() {
+    return totalNanos / count;
+  }
+
   public double meanMillis() {
-    return toMilliSeconds(meanNanos);
+    return toMilliSeconds(meanNanos());
   }
 
   public double medianMillis() {
@@ -75,6 +78,18 @@ class TasksStatistics {
     return toMilliSeconds(totalNanos);
   }
 
+  public double selfMillis() {
+    return toMilliSeconds(selfNanos);
+  }
+
+  public double selfMeanNanos() {
+    return selfNanos / count;
+  }
+
+  public double selfMeanMillis() {
+    return toMilliSeconds(selfMeanNanos());
+  }
+
   /**
    * @param name
    * @param tasks
@@ -102,23 +117,23 @@ class TasksStatistics {
     // Compute standard deviation with a shift to avoid catastrophic cancellation
     // and also do it in milliseconds, as in nanoseconds it overflows
     long sum = 0L;
+    long self = 0L;
     double sumOfSquaredShiftedMillis = 0L;
     final long shift = min;
 
     for (Task task : tasks) {
       sum += task.duration;
+      self += task.duration - task.getInheritedDuration();
       double taskDurationShiftMillis = toMilliSeconds(task.duration - shift);
       sumOfSquaredShiftedMillis += taskDurationShiftMillis * taskDurationShiftMillis;
     }
     double sumShiftedMillis = toMilliSeconds(sum - count * shift);
 
-    double mean = (double) sum / count;
-
     double standardDeviation =
         Math.sqrt(
             (sumOfSquaredShiftedMillis - (sumShiftedMillis * sumShiftedMillis) / count) / count);
 
-    return new TasksStatistics(name, count, min, max, mean, median, standardDeviation, sum);
+    return new TasksStatistics(name, count, min, max, median, standardDeviation, sum, self);
   }
 
   static double toMilliSeconds(double nanoseconds) {
diff --git a/src/main/java/com/google/devtools/build/lib/syntax/BuiltinFunction.java b/src/main/java/com/google/devtools/build/lib/syntax/BuiltinFunction.java
index a7547deca3..e3634f124b 100644
--- a/src/main/java/com/google/devtools/build/lib/syntax/BuiltinFunction.java
+++ b/src/main/java/com/google/devtools/build/lib/syntax/BuiltinFunction.java
@@ -147,7 +147,8 @@ public class BuiltinFunction extends BaseFunction {
       }
     }
 
-    long startTime = Profiler.nanoTimeMaybe();
+    Profiler.instance().startTask(ProfilerTask.SKYLARK_BUILTIN_FN,
+        this.getClass().getName() + "#" + getName());
     // Last but not least, actually make an inner call to the function with the resolved arguments.
     try {
       return invokeMethod.invoke(this, args);
@@ -189,10 +190,7 @@ public class BuiltinFunction extends BaseFunction {
     } catch (IllegalAccessException e) {
       throw badCallException(loc, e, args);
     } finally {
-      Profiler.instance().logSimpleTask(
-          startTime,
-          ProfilerTask.SKYLARK_BUILTIN_FN,
-          this.getClass().getName() + "#" + getName());
+      Profiler.instance().completeTask(ProfilerTask.SKYLARK_BUILTIN_FN);
     }
   }
 
diff --git a/src/main/java/com/google/devtools/build/lib/syntax/UserDefinedFunction.java b/src/main/java/com/google/devtools/build/lib/syntax/UserDefinedFunction.java
index f50e6ee5f1..1ad455da22 100644
--- a/src/main/java/com/google/devtools/build/lib/syntax/UserDefinedFunction.java
+++ b/src/main/java/com/google/devtools/build/lib/syntax/UserDefinedFunction.java
@@ -56,7 +56,8 @@ public class UserDefinedFunction extends BaseFunction {
       env.update(name, arguments[i++]);
     }
 
-    long startTimeProfiler = Profiler.nanoTimeMaybe();
+    Profiler.instance().startTask(ProfilerTask.SKYLARK_USER_FN,
+        getLocationPathAndLine() + "#" + getName());
     Statement lastStatement = null;
     try {
       for (Statement stmt : statements) {
@@ -75,10 +76,7 @@ public class UserDefinedFunction extends BaseFunction {
       real.registerStatement(lastStatement);
       throw real;
     } finally {
-      Profiler.instance().logSimpleTask(
-          startTimeProfiler,
-          ProfilerTask.SKYLARK_USER_FN,
-          getLocationPathAndLine() + "#" + getName());
+      Profiler.instance().completeTask(ProfilerTask.SKYLARK_USER_FN);
     }
     return Runtime.NONE;
   }