Record histogram and other statistics for the ProfileTask objects. In case of recording VFS_ stats we try to catalog the access base on the path type.

--
MOS_MIGRATED_REVID=108238357

6 files changed, 411 insertions, 13 deletions

diff --git a/src/main/java/com/google/devtools/build/lib/profiler/MetricData.java b/src/main/java/com/google/devtools/build/lib/profiler/MetricData.java
new file mode 100644
index 0000000000..db46b0d866
--- /dev/null
+++ b/src/main/java/com/google/devtools/build/lib/profiler/MetricData.java
@@ -0,0 +1,122 @@
+// Copyright 2014 The Bazel Authors. 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;
+
+import com.google.common.base.Joiner;
+import com.google.common.base.Predicate;
+import com.google.common.collect.Collections2;
+import com.google.common.collect.ImmutableList;
+import com.google.common.collect.Range;
+
+import java.text.DecimalFormat;
+
+/**
+ * Metric data for {@code description} object. Contains count, average, standard deviation, max and
+ * histogram.
+ */
+public final class MetricData {
+
+  private final Object description;
+  private final ImmutableList<HistogramElement> histogram;
+  private final int count;
+  private final double avg;
+  private final double stdDev;
+  private final int max;
+  private static final Predicate<HistogramElement> NON_EMPTY_HISTOGRAM_ELEMENT =
+      new Predicate<HistogramElement>() {
+        @Override
+        public boolean apply(HistogramElement element) {
+          return element.count > 0;
+        }
+      };
+
+  public MetricData(Object description, ImmutableList<HistogramElement> histogram, int count,
+      double avg, double stdDev, int max) {
+    this.description = description;
+    this.histogram = histogram;
+    this.count = count;
+    this.avg = avg;
+    this.stdDev = stdDev;
+    this.max = max;
+  }
+
+  public Object getDescription() {
+    return description;
+  }
+
+  public ImmutableList<HistogramElement> getHistogram() {
+    return histogram;
+  }
+
+  public int getCount() {
+    return count;
+  }
+
+  public double getAvg() {
+    return avg;
+  }
+
+  public double getStdDev() {
+    return stdDev;
+  }
+
+  public int getMax() {
+    return max;
+  }
+
+  @Override
+  public String toString() {
+    if (count == 0) {
+      return "'" + description + "'. Zero data recorded";
+    }
+    DecimalFormat fmt = new DecimalFormat("0.###");
+    return "'" + description + "'. "
+        + " Count: " + count
+        + " Avg: " + fmt.format(avg)
+        + " StdDev: " + fmt.format(stdDev)
+        + " Max: " + max
+        + " Histogram:\n  "
+        + Joiner.on("\n  ").join(Collections2.filter(histogram, NON_EMPTY_HISTOGRAM_ELEMENT));
+  }
+
+  /** An histogram element that contains the range that applies to and the number of elements. */
+  public static final class HistogramElement {
+
+    private final Range<Integer> range;
+    private final int count;
+
+    HistogramElement(Range<Integer> range, int count) {
+      this.range = range;
+      this.count = count;
+    }
+
+    public Range<Integer> getRange() {
+      return range;
+    }
+
+    public int getCount() {
+      return count;
+    }
+
+    @Override
+    public String toString() {
+
+      return String.format("%-15s:%10s",
+          "[" + range.lowerEndpoint() + ".." + (range.hasUpperBound()
+                                                ? range.upperEndpoint()
+                                                : "\u221e") // infinite symbol
+              + " ms]", count);
+    }
+  }
+}
diff --git a/src/main/java/com/google/devtools/build/lib/profiler/PredicateBasedStatRecorder.java b/src/main/java/com/google/devtools/build/lib/profiler/PredicateBasedStatRecorder.java
new file mode 100644
index 0000000000..55b0020b23
--- /dev/null
+++ b/src/main/java/com/google/devtools/build/lib/profiler/PredicateBasedStatRecorder.java
@@ -0,0 +1,97 @@
+// Copyright 2014 The Bazel Authors. 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;
+
+import com.google.common.base.Predicate;
+import com.google.common.collect.ImmutableList;
+
+import java.util.List;
+
+/**
+ * A stat recorder that is able to look at the kind of object added and delegate to the appropriate
+ * {@link StatRecorder} based on a predicate.
+ *
+ * <p> Note that the predicates are evaluated in order and delegated only to the first one. That
+ * means that the most specific and cheapest predicates should be passed first.
+ */
+public class PredicateBasedStatRecorder implements StatRecorder {
+
+  private final Predicate[] predicates;
+  private final StatRecorder[] recorders;
+
+  public PredicateBasedStatRecorder(List<RecorderAndPredicate> stats) {
+    predicates = new Predicate[stats.size()];
+    recorders = new StatRecorder[stats.size()];
+    for (int i = 0; i < stats.size(); i++) {
+      RecorderAndPredicate stat = stats.get(i);
+      predicates[i] = stat.predicate;
+      recorders[i] = stat.recorder;
+    }
+  }
+
+  @SuppressWarnings("unchecked")
+  @Override
+  public void addStat(int duration, Object obj) {
+    String description = obj.toString();
+    for (int i = 0; i < predicates.length; i++) {
+      if (predicates[i].apply(description)) {
+        recorders[i].addStat(duration, obj);
+        return;
+      }
+    }
+  }
+
+  @Override
+  public boolean isEmpty() {
+    for (StatRecorder recorder : recorders) {
+      if (!recorder.isEmpty()) {
+        return false;
+      }
+    }
+    return true;
+  }
+
+  @Override
+  public String toString() {
+    StringBuilder sb = new StringBuilder();
+    for (StatRecorder recorder : recorders) {
+      if (recorder.isEmpty()) {
+        continue;
+      }
+      sb.append(recorder);
+      sb.append("\n");
+    }
+    return sb.toString();
+  }
+
+  /**
+   * A Wrapper of a {@code StatRecorder} and a {@code Predicate}. Objects that matches the predicate
+   * will be delegated to the StatRecorder.
+   */
+  public static final class RecorderAndPredicate {
+
+    private final StatRecorder recorder;
+    private final Predicate<? super String> predicate;
+
+    public RecorderAndPredicate(StatRecorder recorder, Predicate<? super String> predicate) {
+      this.recorder = recorder;
+      this.predicate = predicate;
+    }
+  }
+
+  /** Returns all the delegate stat recorders. */
+  public ImmutableList<StatRecorder> getRecorders() {
+    return ImmutableList.<StatRecorder>builder().add(recorders).build();
+  }
+}
diff --git a/src/main/java/com/google/devtools/build/lib/profiler/Profiler.java b/src/main/java/com/google/devtools/build/lib/profiler/Profiler.java
index def46d8983..57ab3b0e58 100644
--- a/src/main/java/com/google/devtools/build/lib/profiler/Profiler.java
+++ b/src/main/java/com/google/devtools/build/lib/profiler/Profiler.java
@@ -16,7 +16,11 @@ package com.google.devtools.build.lib.profiler;
 import static com.google.devtools.build.lib.profiler.ProfilerTask.TASK_COUNT;
 
 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.devtools.build.lib.profiler.PredicateBasedStatRecorder.RecorderAndPredicate;
+import com.google.devtools.build.lib.profiler.StatRecorder.VfsHeuristics;
 import com.google.devtools.build.lib.util.Clock;
 import com.google.devtools.build.lib.util.VarInt;
 
@@ -29,11 +33,13 @@ import java.util.ArrayList;
 import java.util.IdentityHashMap;
 import java.util.List;
 import java.util.Map;
+import java.util.Map.Entry;
 import java.util.PriorityQueue;
 import java.util.Queue;
 import java.util.Timer;
 import java.util.TimerTask;
 import java.util.concurrent.ConcurrentLinkedQueue;
+import java.util.concurrent.TimeUnit;
 import java.util.concurrent.atomic.AtomicInteger;
 import java.util.zip.Deflater;
 import java.util.zip.DeflaterOutputStream;
@@ -130,7 +136,10 @@ public final class Profiler {
    */
   private static final Profiler instance = new Profiler();
 
+  private static final int HISTOGRAM_BUCKETS = 20;
+
   /**
+   *
    * A task that was very slow.
    */
   public final class SlowTask implements Comparable<SlowTask> {
@@ -452,7 +461,10 @@ public final class Profiler {
   private final SlowestTaskAggregator[] slowestTasks =
   new SlowestTaskAggregator[ProfilerTask.values().length];
 
+  private final StatRecorder[] tasksHistograms = new StatRecorder[ProfilerTask.values().length];
+
   private Profiler() {
+    initHistograms();
     for (ProfilerTask task : ProfilerTask.values()) {
       if (task.slowestInstancesCount != 0) {
         slowestTasks[task.ordinal()] = new SlowestTaskAggregator(task.slowestInstancesCount);
@@ -460,6 +472,27 @@ public final class Profiler {
     }
   }
 
+  private void initHistograms() {
+    for (ProfilerTask task : ProfilerTask.values()) {
+      if (task.isVfs()) {
+        Map<String, ? extends Predicate<? super String>> vfsHeuristics =
+            VfsHeuristics.vfsTypeHeuristics;
+        List<RecorderAndPredicate> recorders = new ArrayList<>(vfsHeuristics.size());
+        for (Entry<String, ? extends Predicate<? super String>> e : vfsHeuristics.entrySet()) {
+          recorders.add(new RecorderAndPredicate(
+              new SingleStatRecorder(task + " " + e.getKey(), HISTOGRAM_BUCKETS), e.getValue()));
+        }
+        tasksHistograms[task.ordinal()] = new PredicateBasedStatRecorder(recorders);
+      } else {
+        tasksHistograms[task.ordinal()] = new SingleStatRecorder(task, HISTOGRAM_BUCKETS);
+      }
+    }
+  }
+
+  public ImmutableList<StatRecorder> getTasksHistograms() {
+    return ImmutableList.copyOf(tasksHistograms);
+  }
+
   public static Profiler instance() {
     return instance;
   }
@@ -659,6 +692,7 @@ public final class Profiler {
   }
 
   private synchronized void clear() {
+    initHistograms();
     profileStartTime = 0L;
     if (timer != null) {
       timer.cancel();
@@ -698,6 +732,7 @@ public final class Profiler {
       duration = 0;
     }
 
+    tasksHistograms[type.ordinal()].addStat((int) TimeUnit.NANOSECONDS.toMillis(duration), object);
     TaskData parent = taskStack.peek();
     if (parent != null) {
       parent.aggregateChild(type, duration);
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 b1f7a54247..6fe3f73446 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
@@ -54,19 +54,19 @@ public enum ProfilerTask {
   REMOTE_QUEUE("Remote execution queuing time", 50000000, 0xCC6600, 0),
   REMOTE_SETUP("Remote execution setup", 50000000, 0xA999CC, 0),
   FETCH("Remote execution file fetching", 50000000, 0xBB99CC, 0),
-  VFS_STAT("VFS stat", 10000000, 0x9999FF, 30),
-  VFS_DIR("VFS readdir", 10000000, 0x0066CC, 30),
-  VFS_READLINK("VFS readlink", 10000000, 0x99CCCC, 30),
-  VFS_MD5("VFS md5", 10000000, 0x999999, 30),
-  VFS_XATTR("VFS xattr", 10000000, 0x9999DD, 30),
-  VFS_DELETE("VFS delete", 10000000, 0xFFCC00, 0),
-  VFS_OPEN("VFS open", 10000000, 0x009999, 30),
-  VFS_READ("VFS read", 10000000, 0x99CC33, 30),
-  VFS_WRITE("VFS write", 10000000, 0xFF9900, 30),
-  VFS_GLOB("globbing", -1, 0x999966, 30),
-  VFS_VMFS_STAT("VMFS stat", 10000000, 0x9999FF, 0),
-  VFS_VMFS_DIR("VMFS readdir", 10000000, 0x0066CC, 0),
-  VFS_VMFS_READ("VMFS read", 10000000, 0x99CC33, 0),
+  VFS_STAT("VFS stat", 10000000, 0x9999FF, 30, true),
+  VFS_DIR("VFS readdir", 10000000, 0x0066CC, 30, true),
+  VFS_READLINK("VFS readlink", 10000000, 0x99CCCC, 30, true),
+  VFS_MD5("VFS md5", 10000000, 0x999999, 30, true),
+  VFS_XATTR("VFS xattr", 10000000, 0x9999DD, 30, true),
+  VFS_DELETE("VFS delete", 10000000, 0xFFCC00, 0, true),
+  VFS_OPEN("VFS open", 10000000, 0x009999, 30, true),
+  VFS_READ("VFS read", 10000000, 0x99CC33, 30, true),
+  VFS_WRITE("VFS write", 10000000, 0xFF9900, 30, true),
+  VFS_GLOB("globbing", -1, 0x999966, 30, true),
+  VFS_VMFS_STAT("VMFS stat", 10000000, 0x9999FF, 0, true),
+  VFS_VMFS_DIR("VMFS readdir", 10000000, 0x0066CC, 0, true),
+  VFS_VMFS_READ("VMFS read", 10000000, 0x99CC33, 0, true),
   WAIT("thread wait", 5000000, 0x66CCCC, 0),
   CONFIGURED_TARGET("configured target creation", -1, 0x663300, 0),
   TRANSITIVE_CLOSURE("transitive closure creation", -1, 0x996600, 0),
@@ -104,12 +104,20 @@ public enum ProfilerTask {
   public final int color;
   /** How many of the slowest instances to keep. If 0, no slowest instance calculation is done. */
   public final int slowestInstancesCount;
+  /** True if the metric records VFS operations */
+  private boolean vfs;
 
   ProfilerTask(String description, long minDuration, int color, int slowestInstanceCount) {
+    this(description, minDuration, color, slowestInstanceCount, /*vfs=*/ false);
+  }
+
+  ProfilerTask(String description, long minDuration, int color, int slowestInstanceCount,
+      boolean vfs) {
     this.description = description;
     this.minDuration = minDuration;
     this.color = color;
     this.slowestInstancesCount = slowestInstanceCount;
+    this.vfs = vfs;
   }
 
   ProfilerTask(String description) {
@@ -133,4 +141,8 @@ public enum ProfilerTask {
     }
     return set;
   }
+
+  public boolean isVfs() {
+    return vfs;
+  }
 }
diff --git a/src/main/java/com/google/devtools/build/lib/profiler/SingleStatRecorder.java b/src/main/java/com/google/devtools/build/lib/profiler/SingleStatRecorder.java
new file mode 100644
index 0000000000..b40ffba304
--- /dev/null
+++ b/src/main/java/com/google/devtools/build/lib/profiler/SingleStatRecorder.java
@@ -0,0 +1,86 @@
+// Copyright 2014 The Bazel Authors. 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;
+
+import com.google.common.base.Preconditions;
+import com.google.common.collect.ImmutableList;
+import com.google.common.collect.Range;
+import com.google.devtools.build.lib.concurrent.ThreadSafety.ThreadSafe;
+import com.google.devtools.build.lib.profiler.MetricData.HistogramElement;
+
+/**
+ * A stat recorder that can record time histograms, count of calls, average time, Std. Deviation
+ * and max time.
+ */
+@ThreadSafe
+public class SingleStatRecorder implements StatRecorder {
+
+  private final int buckets;
+  private final Object description;
+  private int[] histogram;
+  private int count = 0;
+  private double avg = 0.0;
+  private double m2 = 0.0;
+  private int max = -1;
+
+  public SingleStatRecorder(Object description, int buckets) {
+    this.description = description;
+    Preconditions.checkArgument(buckets > 1, "At least two buckets (one for bellow start and one"
+        + "for above start) are required");
+    this.buckets = buckets;
+    histogram = new int[buckets];
+  }
+
+  /** Create an snapshot of the the stats recorded up to now. */
+  public MetricData snapshot() {
+    synchronized (this) {
+      ImmutableList.Builder<HistogramElement> result = ImmutableList.builder();
+      result.add(new HistogramElement(Range.closedOpen(0, 1), histogram[0]));
+      int from = 1;
+      for (int i = 1; i < histogram.length - 1; i++) {
+        int to = from << 1;
+        result.add(new HistogramElement(Range.closedOpen(from, to), histogram[i]));
+        from = to;
+      }
+      result.add(new HistogramElement(Range.atLeast(from), histogram[histogram.length - 1]));
+      return new MetricData(description, result.build(), count, avg,
+          Math.sqrt(m2 / (double) count), max);
+    }
+  }
+
+  @Override
+  public void addStat(int duration, Object obj) {
+    int histogramBucket = Math.min(32 - Integer.numberOfLeadingZeros(duration), buckets - 1);
+    synchronized (this) {
+      count++;
+      double delta = duration - avg;
+      avg += delta / count;
+      m2 += delta * (duration - avg);
+      if (duration > max) {
+        max = duration;
+      }
+      histogram[histogramBucket]++;
+    }
+  }
+
+  @Override
+  public boolean isEmpty() {
+    return snapshot().getCount() == 0;
+  }
+
+  @Override
+  public String toString() {
+    return snapshot().toString();
+  }
+}
diff --git a/src/main/java/com/google/devtools/build/lib/profiler/StatRecorder.java b/src/main/java/com/google/devtools/build/lib/profiler/StatRecorder.java
new file mode 100644
index 0000000000..0ad705727d
--- /dev/null
+++ b/src/main/java/com/google/devtools/build/lib/profiler/StatRecorder.java
@@ -0,0 +1,46 @@
+// Copyright 2014 The Bazel Authors. 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;
+
+import com.google.common.base.Predicate;
+import com.google.common.base.Predicates;
+import com.google.common.collect.ImmutableMap;
+
+import java.util.Map;
+
+/** An object that can record time statistics about an object. */
+public interface StatRecorder {
+
+  /** Add a new time statistic for the object {@code obj}. */
+  void addStat(int duration, Object obj);
+
+  /** True if it has not recorded any statistic */
+  boolean isEmpty();
+
+  /** A collection of heuristics for VFS kind of stats in order to detect the filesystem type. */
+  final class VfsHeuristics {
+
+    private VfsHeuristics() {}
+
+    static Map<String, ? extends Predicate<? super String>> vfsTypeHeuristics =
+        ImmutableMap.of(
+            "blaze-out", Predicates.containsPattern("/blaze-out/"),
+            "source", Predicates.<CharSequence>alwaysTrue());
+
+
+    public static void setVfsTypeHeuristics(Map<String, ? extends Predicate<? super String>> map) {
+      vfsTypeHeuristics = map;
+    }
+  }
+}