Add option to add metadata to the JSON profile. This will currently add the build ID, the output base and a date. This data is accessible by clicking on the button labeled with 'M' in the Chrome Trace Viewer. The side effect is that the format of the profile changes from JSON array to JSON object. See https://docs.google.com/document/d/1CvAClvFfyA5R-PhYUmn5OOQtYMH4h6I0nSsKchNAySU/preview# RELNOTES: None PiperOrigin-RevId: 243071398
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 6549d17..9904741 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
@@ -39,10 +39,12 @@ import java.nio.charset.StandardCharsets; import java.time.Duration; import java.util.ArrayList; +import java.util.Date; import java.util.HashMap; import java.util.IdentityHashMap; import java.util.List; import java.util.Map; +import java.util.UUID; import java.util.concurrent.BlockingQueue; import java.util.concurrent.LinkedBlockingDeque; import java.util.concurrent.TimeUnit; @@ -503,12 +505,15 @@ ImmutableSet<ProfilerTask> profiledTasks, OutputStream stream, Format format, - String comment, + String productName, + String outputBase, + UUID buildID, boolean recordAllDurations, Clock clock, long execStartTimeNanos, boolean enabledCpuUsageProfiling, - boolean slimProfile) + boolean slimProfile, + boolean enableJsonMetadata) throws IOException { Preconditions.checkState(!isActive(), "Profiler already active"); initHistograms(); @@ -529,15 +534,28 @@ if (stream != null && format != null) { switch (format) { case BINARY_BAZEL_FORMAT: - writer = new BinaryFormatWriter(stream, execStartTimeNanos, comment); + writer = + new BinaryFormatWriter( + stream, + execStartTimeNanos, + String.format( + "%s profile for %s at %s, build ID: %s", + productName, outputBase, new Date(), buildID)); break; case JSON_TRACE_FILE_FORMAT: - writer = new JsonTraceFileWriter(stream, execStartTimeNanos, slimProfile); + writer = + new JsonTraceFileWriter( + stream, execStartTimeNanos, slimProfile, enableJsonMetadata, outputBase, buildID); break; case JSON_TRACE_FILE_COMPRESSED_FORMAT: writer = new JsonTraceFileWriter( - new GZIPOutputStream(stream), execStartTimeNanos, slimProfile); + new GZIPOutputStream(stream), + execStartTimeNanos, + slimProfile, + enableJsonMetadata, + outputBase, + buildID); } writer.start(); } @@ -992,6 +1010,9 @@ private final ThreadLocal<Boolean> metadataPosted = ThreadLocal.withInitial(() -> Boolean.FALSE); private final boolean slimProfile; + private final boolean enableJsonMetadata; + private final UUID buildID; + private final String outputBase; // The JDK never returns 0 as thread id so we use that as fake thread id for the critical path. private static final long CRITICAL_PATH_THREAD_ID = 0; @@ -1000,10 +1021,19 @@ private static final long SLIM_PROFILE_MAXIMAL_PAUSE_NS = Duration.ofMillis(100).toNanos(); private static final long SLIM_PROFILE_MAXIMAL_DURATION_NS = Duration.ofMillis(250).toNanos(); - JsonTraceFileWriter(OutputStream outStream, long profileStartTimeNanos, boolean slimProfile) { + JsonTraceFileWriter( + OutputStream outStream, + long profileStartTimeNanos, + boolean slimProfile, + boolean enableJsonMetadata, + String outputBase, + UUID buildID) { this.outStream = outStream; this.profileStartTimeNanos = profileStartTimeNanos; this.slimProfile = slimProfile; + this.enableJsonMetadata = enableJsonMetadata; + this.buildID = buildID; + this.outputBase = outputBase; } @Override @@ -1127,6 +1157,16 @@ // The buffer size of 262144 is chosen at random. new OutputStreamWriter( new BufferedOutputStream(outStream, 262144), StandardCharsets.UTF_8))) { + if (enableJsonMetadata) { + writer.beginObject(); + writer.name("otherData"); + writer.beginObject(); + writer.name("build_id").value(buildID.toString()); + writer.name("output_base").value(outputBase); + writer.name("date").value(new Date().toString()); + writer.endObject(); + writer.name("traceEvents"); + } writer.beginArray(); TaskData data; @@ -1209,6 +1249,9 @@ receivedPoisonPill = true; writer.setIndent(" "); writer.endArray(); + if (enableJsonMetadata) { + writer.endObject(); + } } catch (IOException e) { this.savedException = e; if (!receivedPoisonPill) {
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 2e2388e..7b00a73 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
@@ -100,7 +100,6 @@ import java.time.Duration; import java.util.ArrayList; import java.util.Arrays; -import java.util.Date; import java.util.Iterator; import java.util.LinkedHashMap; import java.util.List; @@ -336,14 +335,15 @@ profiledTasks, out, format, - String.format( - "%s profile for %s at %s, build ID: %s", - getProductName(), workspace.getOutputBase(), new Date(), buildID), + getProductName(), + workspace.getOutputBase().toString(), + buildID, recordFullProfilerData, clock, execStartTimeNanos, options.enableCpuUsageProfiling, - options.enableJsonProfileDiet); + options.enableJsonProfileDiet, + options.enableJsonMetadata); // Instead of logEvent() we're calling the low level function to pass the timings we took in // the launcher. We're setting the INIT phase marker so that it follows immediately the // LAUNCH phase.
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 0a1dccf..fb6c606 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
@@ -243,6 +243,16 @@ public boolean enableJsonProfileDiet; @Option( + name = "experimental_json_profile_metadata", + defaultValue = "false", + documentationCategory = OptionDocumentationCategory.LOGGING, + effectTags = {OptionEffectTag.AFFECTS_OUTPUTS, OptionEffectTag.BAZEL_MONITORING}, + help = + "Adds some metadata (e.g. build ID) to the JSON profile." + + " Changes output from JSON array to JSON object format.") + public boolean enableJsonMetadata; + + @Option( name = "profile", defaultValue = "null", documentationCategory = OptionDocumentationCategory.LOGGING,
diff --git a/src/test/java/com/google/devtools/build/lib/profiler/AutoProfilerBenchmark.java b/src/test/java/com/google/devtools/build/lib/profiler/AutoProfilerBenchmark.java index edcabf6..fa0851e 100644 --- a/src/test/java/com/google/devtools/build/lib/profiler/AutoProfilerBenchmark.java +++ b/src/test/java/com/google/devtools/build/lib/profiler/AutoProfilerBenchmark.java
@@ -18,6 +18,7 @@ import com.google.common.collect.ImmutableSet; import com.google.devtools.build.lib.clock.BlazeClock; import com.google.devtools.build.lib.vfs.inmemoryfs.InMemoryFileSystem; +import java.util.UUID; /** * Microbenchmarks for the overhead of {@link AutoProfiler} over using {@link Profiler} manually. @@ -33,11 +34,14 @@ new InMemoryFileSystem().getPath("/out.dat").getOutputStream(), Profiler.Format.BINARY_BAZEL_FORMAT, "benchmark", + "dummy_output_base", + UUID.randomUUID(), false, BlazeClock.instance(), BlazeClock.instance().nanoTime(), /* enabledCpuUsageProfiling= */ false, - /* slimProfile= */ false); + /* slimProfile= */ false, + /* enableJsonMetadata= */ false); } @BeforeExperiment
diff --git a/src/test/java/com/google/devtools/build/lib/profiler/ProfilerChartTest.java b/src/test/java/com/google/devtools/build/lib/profiler/ProfilerChartTest.java index 8134722..dcbb24b 100644 --- a/src/test/java/com/google/devtools/build/lib/profiler/ProfilerChartTest.java +++ b/src/test/java/com/google/devtools/build/lib/profiler/ProfilerChartTest.java
@@ -39,6 +39,7 @@ import java.io.OutputStream; import java.util.List; import java.util.Locale; +import java.util.UUID; import org.junit.Test; import org.junit.runner.RunWith; import org.junit.runners.JUnit4; @@ -256,11 +257,14 @@ out, Profiler.Format.BINARY_BAZEL_FORMAT, "basic test", + "dummy_output_base", + UUID.randomUUID(), false, BlazeClock.instance(), BlazeClock.instance().nanoTime(), /* enabledCpuUsageProfiling= */ false, - /* slimProfile= */ false); + /* slimProfile= */ false, + /* enableJsonMetadata= */ false); // Write from multiple threads to generate multiple rows in the chart. for (int i = 0; i < noOfRows; i++) {
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 0a27faa..f2cd1a5 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
@@ -38,6 +38,7 @@ import java.util.ArrayList; import java.util.Arrays; import java.util.List; +import java.util.UUID; import java.util.concurrent.atomic.AtomicInteger; import java.util.zip.Deflater; import java.util.zip.DeflaterOutputStream; @@ -97,11 +98,14 @@ buffer, format, "test", + "dummy_output_base", + UUID.randomUUID(), false, BlazeClock.instance(), BlazeClock.nanoTime(), /* enabledCpuUsageProfiling= */ false, - /* slimProfile= */ false); + /* slimProfile= */ false, + /* enableJsonMetadata= */ false); return buffer; } @@ -111,11 +115,14 @@ null, null, "test", + "dummy_output_base", + UUID.randomUUID(), false, BlazeClock.instance(), BlazeClock.nanoTime(), /* enabledCpuUsageProfiling= */ false, - /* slimProfile= */ false); + /* slimProfile= */ false, + /* enableJsonMetadata= */ false); } @Test @@ -211,11 +218,14 @@ buffer, BINARY_BAZEL_FORMAT, "basic test", + "dummy_output_base", + UUID.randomUUID(), true, BlazeClock.instance(), BlazeClock.instance().nanoTime(), /* enabledCpuUsageProfiling= */ false, - /* slimProfile= */ false); + /* slimProfile= */ false, + /* enableJsonMetadata= */ false); try (SilentCloseable c = profiler.profile(ProfilerTask.ACTION, "action task")) { // Next task takes less than 10 ms but should be recorded anyway. clock.advanceMillis(1); @@ -242,11 +252,14 @@ buffer, BINARY_BAZEL_FORMAT, "test", + "dummy_output_base", + UUID.randomUUID(), true, BlazeClock.instance(), BlazeClock.instance().nanoTime(), /* enabledCpuUsageProfiling= */ false, - /* slimProfile= */ false); + /* slimProfile= */ false, + /* enableJsonMetadata= */ false); profiler.logSimpleTask(10000, 20000, ProfilerTask.VFS_STAT, "stat"); profiler.logSimpleTask(20000, 30000, ProfilerTask.REMOTE_EXECUTION, "remote execution"); @@ -352,11 +365,14 @@ buffer, BINARY_BAZEL_FORMAT, "test", + "dummy_output_base", + UUID.randomUUID(), true, BlazeClock.instance(), BlazeClock.instance().nanoTime(), /* enabledCpuUsageProfiling= */ false, - /* slimProfile= */ false); + /* slimProfile= */ false, + /* enableJsonMetadata= */ false); profiler.logSimpleTask(10000, 20000, ProfilerTask.VFS_STAT, "stat"); assertThat(ProfilerTask.VFS_STAT.collectsSlowestInstances()).isTrue(); @@ -573,11 +589,14 @@ new ByteArrayOutputStream(), BINARY_BAZEL_FORMAT, "testResilenceToNonDecreasingNanoTimes", + "dummy_output_base", + UUID.randomUUID(), false, badClock, initialNanoTime, /* enabledCpuUsageProfiling= */ false, - /* slimProfile= */ false); + /* slimProfile= */ false, + /* enableJsonMetadata= */ false); profiler.logSimpleTask(badClock.nanoTime(), ProfilerTask.INFO, "some task"); profiler.stop(); } @@ -625,11 +644,14 @@ failingOutputStream, BINARY_BAZEL_FORMAT, "basic test", + "dummy_output_base", + UUID.randomUUID(), false, BlazeClock.instance(), BlazeClock.instance().nanoTime(), /* enabledCpuUsageProfiling= */ false, - /* slimProfile= */ false); + /* slimProfile= */ false, + /* enableJsonMetadata= */ false); profiler.logSimpleTaskDuration( Profiler.nanoTimeMaybe(), Duration.ofSeconds(10), ProfilerTask.INFO, "foo"); try { @@ -653,11 +675,14 @@ failingOutputStream, JSON_TRACE_FILE_FORMAT, "basic test", + "dummy_output_base", + UUID.randomUUID(), false, BlazeClock.instance(), BlazeClock.instance().nanoTime(), /* enabledCpuUsageProfiling= */ false, - /* slimProfile= */ false); + /* slimProfile= */ false, + /* enableJsonMetadata= */ false); profiler.logSimpleTaskDuration( Profiler.nanoTimeMaybe(), Duration.ofSeconds(10), ProfilerTask.INFO, "foo"); try { @@ -675,11 +700,14 @@ outputStream, JSON_TRACE_FILE_FORMAT, "basic test", + "dummy_output_base", + UUID.randomUUID(), false, BlazeClock.instance(), BlazeClock.instance().nanoTime(), /* enabledCpuUsageProfiling= */ false, - slimProfile); + slimProfile, + /* enableJsonMetadata= */ false); long curTime = Profiler.nanoTimeMaybe(); for (int i = 0; i < 100_000; i++) { Duration duration;