Add local action cache hits to the chrome trace profile as stacked chart.

In a future change, we can combine other series of the JSON trace profile, but this is already adding coverage for a former blind spot.

PiperOrigin-RevId: 497144454
Change-Id: Ia9ed67bde49c02a5427380202ff17c904eaccab0

Author: meisterT

src/main/java/com/google/devtools/build/lib/profiler/CollectLocalResourceUsage.java

@@ -18,6 +18,7 @@
 import com.google.common.base.Preconditions;
 import com.google.common.base.Stopwatch;
 import com.google.common.collect.ImmutableList;
+import com.google.common.collect.ImmutableMap;
 import com.google.devtools.build.lib.actions.ResourceEstimator;
 import com.google.devtools.build.lib.bugreport.BugReporter;
 import com.google.devtools.build.lib.profiler.NetworkMetricsCollector.SystemNetworkUsages;
@@ -265,7 +266,9 @@ synchronized void logCollectedData() {
 
     for (ProfilerTask task : timeSeries.keySet()) {
       profiler.logCounters(
-          task, timeSeries.get(task).toDoubleArray(len), profileStart, BUCKET_DURATION);
+          ImmutableMap.ofEntries(Map.entry(task, timeSeries.get(task).toDoubleArray(len))),
+          profileStart,
+          BUCKET_DURATION);
     }
     timeSeries = null;
   }

src/main/java/com/google/devtools/build/lib/profiler/CounterSeriesTraceData.java

@@ -20,38 +20,53 @@
 import com.google.gson.stream.JsonWriter;
 import java.io.IOException;
 import java.time.Duration;
+import java.util.Map;
 import java.util.concurrent.TimeUnit;
 import javax.annotation.Nullable;
 
 /**
- * Used to inject a whole counter series in one go in the JSON trace profile; these could be used to
- * represent CPU or memory usages over the course of an invocations (as opposed to individual tasks
- * such as executing an action).
+ * Used to inject a whole counter series (or even multiple) in one go in the JSON trace profile;
+ * these could be used to represent CPU or memory usages over the course of an invocation (as
+ * opposed to individual tasks such as executing an action).
  */
 final class CounterSeriesTraceData implements TraceData {
-  private final String shortName;
-  private final String readableName;
-  private final double[] counterValues;
+  private final Map<ProfilerTask, double[]> counterSeriesMap;
   private final Duration profileStart;
   private final Duration bucketDuration;
-  @Nullable private final String colorName;
+  private final int len;
+  private String displayName;
+  @Nullable private String colorName;
 
+  /**
+   * If multiple series are passed: - they will be rendered as stacked chart; - we assume they all
+   * have the same length; - display name and color are picked from the first profile task in the
+   * map. However, colors the remaining series are picked arbitrarily by the Trace renderer.
+   */
   CounterSeriesTraceData(
-      ProfilerTask profilerTask,
-      double[] counterValues,
+      Map<ProfilerTask, double[]> counterSeriesMap,
       Duration profileStart,
       Duration bucketDuration) {
-    Preconditions.checkArgument(COUNTER_TASK_TO_SERIES_NAME.containsKey(profilerTask));
-    this.shortName = profilerTask.description;
-    this.readableName = COUNTER_TASK_TO_SERIES_NAME.get(profilerTask);
-    this.counterValues = counterValues;
+    Integer len = null;
+    for (ProfilerTask profilerTask : counterSeriesMap.keySet()) {
+      Preconditions.checkState(COUNTER_TASK_TO_SERIES_NAME.containsKey(profilerTask));
+      if (len == null) {
+        len = counterSeriesMap.get(profilerTask).length;
+
+        this.displayName = profilerTask.description;
+
+        // Pick acceptable counter colors manually, unfortunately we have to pick from these
+        // weird reserved names from
+        // https://github.com/catapult-project/catapult/blob/master/tracing/tracing/base/color_scheme.html
+        this.colorName = COUNTER_TASK_TO_COLOR.get(profilerTask);
+      } else {
+        Preconditions.checkState(len.equals(counterSeriesMap.get(profilerTask).length));
+      }
+    }
+    this.len = len;
+    this.counterSeriesMap = counterSeriesMap;
     this.profileStart = profileStart;
     this.bucketDuration = bucketDuration;
 
-    // Pick acceptable counter colors manually, unfortunately we have to pick from these
-    // weird reserved names from
-    // https://github.com/catapult-project/catapult/blob/master/tracing/tracing/base/color_scheme.html
-    this.colorName = COUNTER_TASK_TO_COLOR.get(profilerTask);
   }
 
   // Pick acceptable counter colors manually, unfortunately we have to pick from these
@@ -73,6 +88,7 @@ final class CounterSeriesTraceData implements TraceData {
   private static final ImmutableMap<ProfilerTask, String> COUNTER_TASK_TO_SERIES_NAME =
       ImmutableMap.ofEntries(
           entry(ProfilerTask.ACTION_COUNTS, "action"),
+          entry(ProfilerTask.ACTION_CACHE_COUNTS, "local action cache"),
           entry(ProfilerTask.LOCAL_CPU_USAGE, "cpu"),
           entry(ProfilerTask.SYSTEM_CPU_USAGE, "system cpu"),
           entry(ProfilerTask.LOCAL_MEMORY_USAGE, "memory"),
@@ -86,18 +102,15 @@ final class CounterSeriesTraceData implements TraceData {
 
   @Override
   public void writeTraceData(JsonWriter jsonWriter, long profileStartTimeNanos) throws IOException {
-    // See https://docs.google.com/document/d/1CvAClvFfyA5R-PhYUmn5OOQtYMH4h6I0nSsKchNAySU/preview#heading=h.msg3086636uq
+    // See
+    // https://docs.google.com/document/d/1CvAClvFfyA5R-PhYUmn5OOQtYMH4h6I0nSsKchNAySU/preview#heading=h.msg3086636uq
     // for how counter series are represented in the Chrome Trace Event format.
-    for (int i = 0; i < counterValues.length; i++) {
+    for (int i = 0; i < len; i++) {
       long timeNanos = profileStart.plus(bucketDuration.multipliedBy(i)).toNanos();
-      // Skip counts equal to zero. They will show up as a thin line in the profile.
-      if (Math.abs(counterValues[i]) <= 0.00001) {
-        continue;
-      }
       jsonWriter.setIndent("  ");
       jsonWriter.beginObject();
       jsonWriter.setIndent("");
-      jsonWriter.name("name").value(shortName);
+      jsonWriter.name("name").value(displayName);
       jsonWriter.name("pid").value(1);
       if (colorName != null) {
         jsonWriter.name("cname").value(colorName);
@@ -107,7 +120,13 @@ public void writeTraceData(JsonWriter jsonWriter, long profileStartTimeNanos) th
       jsonWriter.name("args");
 
       jsonWriter.beginObject();
-      jsonWriter.name(readableName).value(counterValues[i]);
+      for (ProfilerTask profilerTask : counterSeriesMap.keySet()) {
+        double value = counterSeriesMap.get(profilerTask)[i];
+        // Skip counts equal to zero. They will show up as a thin line in the profile.
+        if (Math.abs(value) > 0.00001) {
+          jsonWriter.name(COUNTER_TASK_TO_SERIES_NAME.get(profilerTask)).value(value);
+        }
+      }
       jsonWriter.endObject();
 
       jsonWriter.endObject();

src/main/java/com/google/devtools/build/lib/profiler/Profiler.java

@@ -37,6 +37,7 @@
 import java.time.Duration;
 import java.util.ArrayList;
 import java.util.Arrays;
+import java.util.LinkedHashMap;
 import java.util.List;
 import java.util.Map;
 import java.util.UUID;
@@ -344,6 +345,7 @@ public double getCounterValue() {
   private CollectLocalResourceUsage resourceUsageThread;
 
   private TimeSeries actionCountTimeSeries;
+  private TimeSeries actionCacheCountTimeSeries;
   private Duration actionCountStartTime;
   private boolean collectTaskHistograms;
   private boolean includePrimaryOutput;
@@ -473,6 +475,8 @@ public synchronized void start(
     this.clock = clock;
     this.actionCountStartTime = Duration.ofNanos(clock.nanoTime());
     this.actionCountTimeSeries = new TimeSeries(actionCountStartTime, ACTION_COUNT_BUCKET_DURATION);
+    this.actionCacheCountTimeSeries =
+        new TimeSeries(actionCountStartTime, ACTION_COUNT_BUCKET_DURATION);
     this.collectTaskHistograms = collectTaskHistograms;
     this.includePrimaryOutput = includePrimaryOutput;
     this.includeTargetLabel = includeTargetLabel;
@@ -536,17 +540,21 @@ public synchronized Iterable<SlowTask> getSlowestTasks() {
   }
 
   private void collectActionCounts() {
+    Duration endTime = Duration.ofNanos(clock.nanoTime());
+    int len = (int) endTime.minus(actionCountStartTime).dividedBy(ACTION_COUNT_BUCKET_DURATION) + 1;
+    Map<ProfilerTask, double[]> counterSeriesMap = new LinkedHashMap<>();
     if (actionCountTimeSeries != null) {
-      Duration endTime = Duration.ofNanos(clock.nanoTime());
-      Duration profileStart = actionCountStartTime;
-      int len = (int) endTime.minus(profileStart).dividedBy(ACTION_COUNT_BUCKET_DURATION) + 1;
       double[] actionCountValues = actionCountTimeSeries.toDoubleArray(len);
-      instance.logCounters(
-          ProfilerTask.ACTION_COUNTS,
-          actionCountValues,
-          profileStart,
-          ACTION_COUNT_BUCKET_DURATION);
       actionCountTimeSeries = null;
+      counterSeriesMap.put(ProfilerTask.ACTION_COUNTS, actionCountValues);
+    }
+    if (actionCacheCountTimeSeries != null) {
+      double[] actionCacheCountValues = actionCacheCountTimeSeries.toDoubleArray(len);
+      actionCacheCountTimeSeries = null;
+      counterSeriesMap.put(ProfilerTask.ACTION_CACHE_COUNTS, actionCacheCountValues);
+    }
+    if (!counterSeriesMap.isEmpty()) {
+      instance.logCounters(counterSeriesMap, actionCountStartTime, ACTION_COUNT_BUCKET_DURATION);
     }
   }
 
@@ -609,11 +617,13 @@ private boolean wasTaskSlowEnoughToRecord(ProfilerTask type, long duration) {
 
   /** Adds a whole action count series to the writer bypassing histogram and subtask creation. */
   public void logCounters(
-      ProfilerTask type, double[] counterValues, Duration profileStart, Duration bucketDuration) {
+      Map<ProfilerTask, double[]> counterSeriesMap,
+      Duration profileStart,
+      Duration bucketDuration) {
     JsonTraceFileWriter currentWriter = writerRef.get();
-    if (isActive() && isProfiling(type) && currentWriter != null) {
+    if (isActive() && currentWriter != null) {
       CounterSeriesTraceData counterSeriesTraceData =
-          new CounterSeriesTraceData(type, counterValues, profileStart, bucketDuration);
+          new CounterSeriesTraceData(counterSeriesMap, profileStart, bucketDuration);
       currentWriter.enqueue(counterSeriesTraceData);
     }
   }
@@ -832,17 +842,22 @@ private void completeTask(TaskData data) {
       data.duration = endTime - data.startTimeNanos;
       boolean shouldRecordTask = wasTaskSlowEnoughToRecord(data.type, data.duration);
       JsonTraceFileWriter writer = writerRef.get();
-      if (shouldRecordTask && writer != null) {
-        writer.enqueue(data);
-      }
-
       if (shouldRecordTask) {
+        if (writer != null) {
+          writer.enqueue(data);
+        }
         if (actionCountTimeSeries != null && countAction(data.type, data)) {
           synchronized (this) {
             actionCountTimeSeries.addRange(
                 Duration.ofNanos(data.startTimeNanos), Duration.ofNanos(endTime));
           }
         }
+        if (actionCacheCountTimeSeries != null && data.type == ProfilerTask.ACTION_CHECK) {
+          synchronized (this) {
+            actionCacheCountTimeSeries.addRange(
+                Duration.ofNanos(data.startTimeNanos), Duration.ofNanos(endTime));
+          }
+        }
         SlowestTaskAggregator aggregator = slowestTasks[data.type.ordinal()];
         if (aggregator != null) {
           aggregator.add(data);

src/main/java/com/google/devtools/build/lib/profiler/ProfilerTask.java

@@ -65,6 +65,7 @@ public enum ProfilerTask {
   CRITICAL_PATH_COMPONENT("critical path component"),
   HANDLE_GC_NOTIFICATION("gc notification"),
   ACTION_COUNTS("action count"),
+  ACTION_CACHE_COUNTS("action cache count"),
   LOCAL_CPU_USAGE("CPU usage (Bazel)"),
   SYSTEM_CPU_USAGE("CPU usage (total)"),
   CPU_USAGE_ESTIMATION("CPU usage estimation"),

src/main/java/com/google/devtools/build/lib/profiler/TraceEvent.java

@@ -36,21 +36,35 @@ public abstract class TraceEvent {
   public static TraceEvent create(
       @Nullable String category,
       String name,
+      @Nullable String type,
       @Nullable Duration timestamp,
       @Nullable Duration duration,
       long threadId,
+      @Nullable ImmutableMap<String, Object> args,
       @Nullable String primaryOutputPath,
       @Nullable String targetLabel,
       @Nullable String mnemonic) {
     return new AutoValue_TraceEvent(
-        category, name, timestamp, duration, threadId, primaryOutputPath, targetLabel, mnemonic);
+        category,
+        name,
+        type,
+        timestamp,
+        duration,
+        threadId,
+        args,
+        primaryOutputPath,
+        targetLabel,
+        mnemonic);
   }
 
   @Nullable
   public abstract String category();
 
   public abstract String name();
 
+  @Nullable
+  public abstract String type();
+
   @Nullable
   public abstract Duration timestamp();
 
@@ -59,6 +73,9 @@ public static TraceEvent create(
 
   public abstract long threadId();
 
+  @Nullable
+  public abstract ImmutableMap<String, Object> args();
+
   // Only applicable to action-related TraceEvents.
   @Nullable
   public abstract String primaryOutputPath();
@@ -78,6 +95,8 @@ private static TraceEvent createFromJsonReader(JsonReader reader) throws IOExcep
     String primaryOutputPath = null;
     String targetLabel = null;
     String mnemonic = null;
+    String type = null;
+    ImmutableMap<String, Object> args = null;
 
     reader.beginObject();
     while (reader.hasNext()) {
@@ -88,6 +107,9 @@ private static TraceEvent createFromJsonReader(JsonReader reader) throws IOExcep
         case "name":
           name = reader.nextString();
           break;
+        case "ph":
+          type = reader.nextString();
+          break;
         case "ts":
           // Duration has no microseconds :-/.
           timestamp = Duration.ofNanos(reader.nextLong() * 1000);
@@ -102,7 +124,7 @@ private static TraceEvent createFromJsonReader(JsonReader reader) throws IOExcep
           primaryOutputPath = reader.nextString();
           break;
         case "args":
-          ImmutableMap<String, Object> args = parseMap(reader);
+          args = parseMap(reader);
           Object target = args.get("target");
           targetLabel = target instanceof String ? (String) target : null;
           Object mnemonicValue = args.get("mnemonic");
@@ -114,7 +136,16 @@ private static TraceEvent createFromJsonReader(JsonReader reader) throws IOExcep
     }
     reader.endObject();
     return TraceEvent.create(
-        category, name, timestamp, duration, threadId, primaryOutputPath, targetLabel, mnemonic);
+        category,
+        name,
+        type,
+        timestamp,
+        duration,
+        threadId,
+        args,
+        primaryOutputPath,
+        targetLabel,
+        mnemonic);
   }
 
   private static ImmutableMap<String, Object> parseMap(JsonReader reader) throws IOException {