Add support for the Json trace file format

Add a --experimental_generate_json_trace_profile option that puts a file into
the output base (or uses --profile if set).

There are still a lot of problems with this.
- unexplained holes
- way too many threads
- nonsensical event titles
- too many detail events, too little overview
- it may also cause unnecessary load
- it silently overwrites the existing file on subsequent invocations

The format is documented here: goo.gl/oMZPLh

PiperOrigin-RevId: 200259431

5 files changed, 147 insertions, 6 deletions

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 80f04cedd2..88634d4e63 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
@@ -30,7 +30,10 @@ import java.io.BufferedOutputStream;
 import java.io.DataOutputStream;
 import java.io.IOException;
 import java.io.OutputStream;
+import java.io.OutputStreamWriter;
+import java.io.Writer;
 import java.nio.ByteBuffer;
+import java.nio.charset.StandardCharsets;
 import java.time.Duration;
 import java.util.ArrayList;
 import java.util.IdentityHashMap;
@@ -138,7 +141,8 @@ public final class Profiler {
 
   /** File format enum. */
   public static enum Format {
-    BINARY_BAZEL_FORMAT;
+    BINARY_BAZEL_FORMAT,
+    JSON_TRACE_FILE_FORMAT;
   }
 
   /** A task that was very slow. */
@@ -408,6 +412,17 @@ public final class Profiler {
       }
     },
 
+    /** A set of tasks that's useful for the Json trace output. */
+    ALL_FOR_TRACE {
+      @Override
+      boolean isProfiling(ProfilerTask type) {
+        return !type.isVfs()
+            // Exclude the critical path - it's not useful in the Json trace output.
+            && type != ProfilerTask.CRITICAL_PATH
+            && type != ProfilerTask.CRITICAL_PATH_COMPONENT;
+      }
+    },
+
     /**
      * Profile all tasks.
      *
@@ -551,6 +566,9 @@ public final class Profiler {
       if (format == Format.BINARY_BAZEL_FORMAT) {
         writer = new BinaryFormatWriter(stream, profileStartTime, comment);
         writer.start();
+      } else if (format == Format.JSON_TRACE_FILE_FORMAT) {
+        writer = new JsonTraceFileWriter(stream, profileStartTime);
+        writer.start();
       }
     }
     this.writerRef.set(writer);
@@ -949,4 +967,81 @@ public final class Profiler {
       }
     }
   }
+
+  /** Writes the profile in Json Trace file format. */
+  private static class JsonTraceFileWriter extends FileWriter {
+    private final Writer out;
+    private final long profileStartTimeNanos;
+
+    JsonTraceFileWriter(
+        OutputStream out,
+        long profileStartTimeNanos) {
+      this.out =
+          // The buffer size of 262144 is chosen at random. We might also want to use compression
+          // in the future.
+          new OutputStreamWriter(new BufferedOutputStream(out, 262144), StandardCharsets.UTF_8);
+      this.profileStartTimeNanos = profileStartTimeNanos;
+    }
+
+    /**
+     * Saves all gathered information from taskQueue queue to the file.
+     * Method is invoked internally by the Timer-based thread and at the end of
+     * profiling session.
+     */
+    @Override
+    public void run() {
+      try {
+        boolean receivedPoisonPill = false;
+        try {
+          out.append("[");
+          boolean first = true;
+          TaskData data;
+          while ((data = queue.take()) != POISON_PILL) {
+            if (data.duration == 0) {
+              continue;
+            }
+            if (first) {
+              first = false;
+            } else {
+              out.append(",");
+            }
+            char eventType = data.duration == 0 ? 'i' : 'X';
+            out.append("{");
+            out.append("\"name\":\"").append(data.description).append("\",");
+            out.append("\"ph\":\"").append(eventType).append("\",");
+            out.append("\"ts\":")
+                .append(
+                    Long.toString(
+                        TimeUnit.NANOSECONDS.toMicros(data.startTimeNanos - profileStartTimeNanos)))
+                .append(",");
+            if (data.duration != 0) {
+              out.append("\"dur\":")
+                  .append(Long.toString(TimeUnit.NANOSECONDS.toMicros(data.duration)))
+                  .append(",");
+            }
+            out.append("\"pid\":1,");
+            out.append("\"tid\":").append(Long.toString(data.threadId));
+            out.append("}\n");
+          }
+          receivedPoisonPill = true;
+          out.append("]");
+          out.close();
+        } catch (IOException e) {
+          this.savedException = e;
+          try {
+            out.close();
+          } catch (IOException e2) {
+            // ignore it
+          }
+          if (!receivedPoisonPill) {
+            while (queue.take() != POISON_PILL) {
+              // We keep emptying the queue, but we can't write anything.
+            }
+          }
+        }
+      } catch (InterruptedException e) {
+        // Exit silently.
+      }
+    }
+  }
 }
diff --git a/src/main/java/com/google/devtools/build/lib/runtime/BlazeRuntime.java b/src/main/java/com/google/devtools/build/lib/runtime/BlazeRuntime.java
index a7b1a96a0c..cb7dd06472 100644
--- a/src/main/java/com/google/devtools/build/lib/runtime/BlazeRuntime.java
+++ b/src/main/java/com/google/devtools/build/lib/runtime/BlazeRuntime.java
@@ -272,7 +272,15 @@ public final class BlazeRuntime {
     ProfiledTaskKinds profiledTasks = ProfiledTaskKinds.NONE;
 
     try {
-      if (options.profilePath != null) {
+      if (options.enableTracer) {
+        Path profilePath = options.profilePath != null
+            ? env.getWorkspace().getRelative(options.profilePath)
+            : env.getOutputBase().getRelative("command.profile");
+        recordFullProfilerData = false;
+        out = profilePath.getOutputStream();
+        env.getReporter().handle(Event.info("Writing tracer profile to '" + profilePath + "'"));
+        profiledTasks = ProfiledTaskKinds.ALL_FOR_TRACE;
+      } else if (options.profilePath != null) {
         Path profilePath = env.getWorkspace().getRelative(options.profilePath);
 
         recordFullProfilerData = options.recordFullProfilerData;
diff --git a/src/main/java/com/google/devtools/build/lib/runtime/CommonCommandOptions.java b/src/main/java/com/google/devtools/build/lib/runtime/CommonCommandOptions.java
index 6e9ba86492..923ebe6693 100644
--- a/src/main/java/com/google/devtools/build/lib/runtime/CommonCommandOptions.java
+++ b/src/main/java/com/google/devtools/build/lib/runtime/CommonCommandOptions.java
@@ -194,6 +194,17 @@ public class CommonCommandOptions extends OptionsBase {
   public String buildRequestId;
 
   @Option(
+    name = "experimental_generate_json_trace_profile",
+    defaultValue = "false",
+    documentationCategory = OptionDocumentationCategory.LOGGING,
+    effectTags = {OptionEffectTag.AFFECTS_OUTPUTS, OptionEffectTag.BAZEL_MONITORING},
+    help =
+        "If enabled, Bazel profiles the build and writes a JSON-format profile into a file in the "
+            + "output base."
+  )
+  public boolean enableTracer;
+
+  @Option(
     name = "profile",
     defaultValue = "null",
     documentationCategory = OptionDocumentationCategory.LOGGING,
diff --git a/src/main/java/com/google/devtools/build/skyframe/AbstractParallelEvaluator.java b/src/main/java/com/google/devtools/build/skyframe/AbstractParallelEvaluator.java
index 2373959857..0c94277a4b 100644
--- a/src/main/java/com/google/devtools/build/skyframe/AbstractParallelEvaluator.java
+++ b/src/main/java/com/google/devtools/build/skyframe/AbstractParallelEvaluator.java
@@ -375,19 +375,19 @@ public abstract class AbstractParallelEvaluator {
                 state);
 
         SkyValue value = null;
-        long startTime = BlazeClock.instance().nanoTime();
+        long startTimeNanos = BlazeClock.instance().nanoTime();
         try {
           try {
             evaluatorContext.getProgressReceiver().stateStarting(skyKey, NodeState.COMPUTE);
             value = factory.compute(skyKey, env);
           } finally {
-            long elapsedTimeNanos = BlazeClock.instance().nanoTime() - startTime;
+            long elapsedTimeNanos = BlazeClock.instance().nanoTime() - startTimeNanos;
             if (elapsedTimeNanos > 0) {
               evaluatorContext.getProgressReceiver().stateEnding(skyKey, NodeState.COMPUTE,
                   elapsedTimeNanos);
               Profiler.instance()
                   .logSimpleTaskDuration(
-                      startTime,
+                      startTimeNanos,
                       Duration.ofNanos(elapsedTimeNanos),
                       ProfilerTask.SKYFUNCTION,
                       skyKey.functionName().getName());
diff --git a/src/test/java/com/google/devtools/build/lib/profiler/ProfilerTest.java b/src/test/java/com/google/devtools/build/lib/profiler/ProfilerTest.java
index 0fee59186d..a52bc2e6e7 100644
--- a/src/test/java/com/google/devtools/build/lib/profiler/ProfilerTest.java
+++ b/src/test/java/com/google/devtools/build/lib/profiler/ProfilerTest.java
@@ -15,6 +15,7 @@ package com.google.devtools.build.lib.profiler;
 
 import static com.google.common.truth.Truth.assertThat;
 import static com.google.devtools.build.lib.profiler.Profiler.Format.BINARY_BAZEL_FORMAT;
+import static com.google.devtools.build.lib.profiler.Profiler.Format.JSON_TRACE_FILE_FORMAT;
 import static java.nio.charset.StandardCharsets.ISO_8859_1;
 import static org.junit.Assert.fail;
 
@@ -573,7 +574,7 @@ public class ProfilerTest {
   }
 
   @Test
-  public void testIOExceptionInOutputStream() throws Exception {
+  public void testIOExceptionInOutputStreamBinaryFormat() throws Exception {
     OutputStream failingOutputStream = new OutputStream() {
       @Override
       public void write(int b) throws IOException {
@@ -597,4 +598,30 @@ public class ProfilerTest {
       assertThat(expected).hasMessageThat().isEqualTo("Expected failure.");
     }
   }
+
+  @Test
+  public void testIOExceptionInOutputStreamJsonFormat() throws Exception {
+    OutputStream failingOutputStream = new OutputStream() {
+      @Override
+      public void write(int b) throws IOException {
+        throw new IOException("Expected failure.");
+      }
+    };
+    profiler.start(
+        ProfiledTaskKinds.ALL,
+        failingOutputStream,
+        JSON_TRACE_FILE_FORMAT,
+        "basic test",
+        false,
+        BlazeClock.instance(),
+        BlazeClock.instance().nanoTime());
+    profiler.logSimpleTaskDuration(
+        Profiler.nanoTimeMaybe(), Duration.ofSeconds(10), ProfilerTask.INFO, "foo");
+    try {
+      profiler.stop();
+      fail();
+    } catch (IOException expected) {
+      assertThat(expected).hasMessageThat().isEqualTo("Expected failure.");
+    }
+  }
 }