Add option to slim down the JSON profile.
If the JSON profile contains many events, we will start merging short events that are close to each other on the same thread.
The event count threshold is chosen high enough to show all data for small clean builds and incremental builds.
With this profile thinning, profiles for big builds that did crash chrome://tracing before, do now load. By keeping all events that are not short we still see all interesting data.
RELNOTES: None
PiperOrigin-RevId: 239609724
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 a7b9cb0..6549d17 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,6 +39,7 @@
import java.nio.charset.StandardCharsets;
import java.time.Duration;
import java.util.ArrayList;
+import java.util.HashMap;
import java.util.IdentityHashMap;
import java.util.List;
import java.util.Map;
@@ -217,6 +218,16 @@
this.description = Preconditions.checkNotNull(description);
}
+ TaskData(long threadId, long startTimeNanos, long duration, String description) {
+ this.id = -1;
+ this.parentId = 0;
+ this.type = ProfilerTask.UNKNOWN;
+ this.threadId = threadId;
+ this.startTimeNanos = startTimeNanos;
+ this.duration = duration;
+ this.description = description;
+ }
+
/** Aggregates information about an *immediate* subtask. */
public void aggregateChild(ProfilerTask type, long duration) {
int index = type.ordinal();
@@ -496,7 +507,8 @@
boolean recordAllDurations,
Clock clock,
long execStartTimeNanos,
- boolean enabledCpuUsageProfiling)
+ boolean enabledCpuUsageProfiling,
+ boolean slimProfile)
throws IOException {
Preconditions.checkState(!isActive(), "Profiler already active");
initHistograms();
@@ -520,10 +532,12 @@
writer = new BinaryFormatWriter(stream, execStartTimeNanos, comment);
break;
case JSON_TRACE_FILE_FORMAT:
- writer = new JsonTraceFileWriter(stream, execStartTimeNanos);
+ writer = new JsonTraceFileWriter(stream, execStartTimeNanos, slimProfile);
break;
case JSON_TRACE_FILE_COMPRESSED_FORMAT:
- writer = new JsonTraceFileWriter(new GZIPOutputStream(stream), execStartTimeNanos);
+ writer =
+ new JsonTraceFileWriter(
+ new GZIPOutputStream(stream), execStartTimeNanos, slimProfile);
}
writer.start();
}
@@ -977,12 +991,19 @@
private final long profileStartTimeNanos;
private final ThreadLocal<Boolean> metadataPosted =
ThreadLocal.withInitial(() -> Boolean.FALSE);
+ private final boolean slimProfile;
+
// 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;
- JsonTraceFileWriter(OutputStream outStream, long profileStartTimeNanos) {
+ private static final long SLIM_PROFILE_EVENT_THRESHOLD = 10_000;
+ 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) {
this.outStream = outStream;
this.profileStartTimeNanos = profileStartTimeNanos;
+ this.slimProfile = slimProfile;
}
@Override
@@ -1001,6 +1022,97 @@
queue.add(data);
}
+ private static final class MergedEvent {
+ int count = 0;
+ long startTimeNanos;
+ long endTimeNanos;
+ TaskData data;
+
+ /*
+ * Tries to merge an additional event, i.e. if the event is close enough to the already merged
+ * event.
+ *
+ * Returns null, if merging was possible.
+ * If not mergeable, returns the TaskData of the previously merged events and clears the
+ * internal data structures.
+ */
+ TaskData maybeMerge(TaskData data) {
+ long startTimeNanos = data.startTimeNanos;
+ long endTimeNanos = startTimeNanos + data.duration;
+ if (count > 0
+ && startTimeNanos >= this.startTimeNanos
+ && endTimeNanos <= this.endTimeNanos) {
+ // Skips child tasks.
+ return null;
+ }
+ if (count == 0) {
+ this.data = data;
+ this.startTimeNanos = startTimeNanos;
+ this.endTimeNanos = endTimeNanos;
+ count++;
+ return null;
+ } else if (startTimeNanos <= this.endTimeNanos + SLIM_PROFILE_MAXIMAL_PAUSE_NS) {
+ this.endTimeNanos = endTimeNanos;
+ count++;
+ return null;
+ } else {
+ TaskData ret = getAndReset();
+ this.startTimeNanos = startTimeNanos;
+ this.endTimeNanos = endTimeNanos;
+ this.data = data;
+ count = 1;
+ return ret;
+ }
+ }
+
+ // Returns a TaskData object representing the merged data and clears internal data structures.
+ TaskData getAndReset() {
+ TaskData ret;
+ if (count <= 1) {
+ ret = data;
+ } else {
+ if (data == null) {
+ ret = data;
+ }
+ ret =
+ new TaskData(
+ data.threadId,
+ this.startTimeNanos,
+ this.endTimeNanos - this.startTimeNanos,
+ "merged " + count + " events");
+ }
+ count = 0;
+ data = null;
+ return ret;
+ }
+ }
+
+ private void writeTask(JsonWriter writer, TaskData data) throws IOException {
+ String eventType = data.duration == 0 ? "i" : "X";
+ writer.setIndent(" ");
+ writer.beginObject();
+ writer.setIndent("");
+ if (data == null || data.type == null) {
+ writer.setIndent(" ");
+ }
+ writer.name("cat").value(data.type.description);
+ writer.name("name").value(data.description);
+ writer.name("ph").value(eventType);
+ writer
+ .name("ts")
+ .value(TimeUnit.NANOSECONDS.toMicros(data.startTimeNanos - profileStartTimeNanos));
+ if (data.duration != 0) {
+ writer.name("dur").value(TimeUnit.NANOSECONDS.toMicros(data.duration));
+ }
+ writer.name("pid").value(1);
+ long threadId =
+ data.type == ProfilerTask.CRITICAL_PATH_COMPONENT
+ ? CRITICAL_PATH_THREAD_ID
+ : data.threadId;
+ writer.name("tid").value(threadId);
+ writer.endObject();
+ }
+
/**
* Saves all gathered information from taskQueue queue to the file.
* Method is invoked internally by the Timer-based thread and at the end of
@@ -1032,7 +1144,10 @@
writer.endObject();
writer.endObject();
+ HashMap<Long, MergedEvent> eventsPerThread = new HashMap<>();
+ int eventCount = 0;
while ((data = queue.take()) != POISON_PILL) {
+ eventCount++;
if (data.type == ProfilerTask.THREAD_NAME) {
writer.setIndent(" ");
writer.beginObject();
@@ -1071,25 +1186,25 @@
writer.endObject();
continue;
}
- String eventType = data.duration == 0 ? "i" : "X";
- writer.setIndent(" ");
- writer.beginObject();
- writer.setIndent("");
- writer.name("cat").value(data.type.description);
- writer.name("name").value(data.description);
- writer.name("ph").value(eventType);
- writer.name("ts")
- .value(TimeUnit.NANOSECONDS.toMicros(data.startTimeNanos - profileStartTimeNanos));
- if (data.duration != 0) {
- writer.name("dur").value(TimeUnit.NANOSECONDS.toMicros(data.duration));
+ if (slimProfile
+ && eventCount > SLIM_PROFILE_EVENT_THRESHOLD
+ && data.duration > 0
+ && data.duration < SLIM_PROFILE_MAXIMAL_DURATION_NS
+ && data.type != ProfilerTask.CRITICAL_PATH_COMPONENT) {
+ eventsPerThread.putIfAbsent(data.threadId, new MergedEvent());
+ TaskData taskData = eventsPerThread.get(data.threadId).maybeMerge(data);
+ if (taskData != null) {
+ writeTask(writer, taskData);
+ }
+ } else {
+ writeTask(writer, data);
}
- writer.name("pid").value(1);
- long threadId =
- data.type == ProfilerTask.CRITICAL_PATH_COMPONENT
- ? CRITICAL_PATH_THREAD_ID
- : data.threadId;
- writer.name("tid").value(threadId);
- writer.endObject();
+ }
+ for (Profiler.JsonTraceFileWriter.MergedEvent value : eventsPerThread.values()) {
+ TaskData taskData = value.getAndReset();
+ if (taskData != null) {
+ writeTask(writer, taskData);
+ }
}
receivedPoisonPill = true;
writer.setIndent(" ");
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 a9afc56..92fa8ff 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
@@ -342,7 +342,8 @@
recordFullProfilerData,
clock,
execStartTimeNanos,
- options.enableCpuUsageProfiling);
+ options.enableCpuUsageProfiling,
+ options.enableJsonProfileDiet);
// 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 9452400..0a1dccf 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
@@ -233,6 +233,16 @@
public List<ProfilerTask> additionalProfileTasks;
@Option(
+ name = "experimental_slim_json_profile",
+ defaultValue = "false",
+ documentationCategory = OptionDocumentationCategory.LOGGING,
+ effectTags = {OptionEffectTag.AFFECTS_OUTPUTS, OptionEffectTag.BAZEL_MONITORING},
+ help =
+ "Slims down the size of the JSON profile by merging events if the profile gets "
+ + " too large.")
+ public boolean enableJsonProfileDiet;
+
+ @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 88eb503..edcabf6 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
@@ -36,7 +36,8 @@
false,
BlazeClock.instance(),
BlazeClock.instance().nanoTime(),
- /* enabledCpuUsageProfiling= */ false);
+ /* enabledCpuUsageProfiling= */ false,
+ /* slimProfile= */ 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 8463222..8134722 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
@@ -259,7 +259,8 @@
false,
BlazeClock.instance(),
BlazeClock.instance().nanoTime(),
- /* enabledCpuUsageProfiling= */ false);
+ /* enabledCpuUsageProfiling= */ false,
+ /* slimProfile= */ 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 eef9405..0a27faa 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
@@ -100,7 +100,8 @@
false,
BlazeClock.instance(),
BlazeClock.nanoTime(),
- /* enabledCpuUsageProfiling= */ false);
+ /* enabledCpuUsageProfiling= */ false,
+ /* slimProfile= */ false);
return buffer;
}
@@ -113,7 +114,8 @@
false,
BlazeClock.instance(),
BlazeClock.nanoTime(),
- /* enabledCpuUsageProfiling= */ false);
+ /* enabledCpuUsageProfiling= */ false,
+ /* slimProfile= */ false);
}
@Test
@@ -212,7 +214,8 @@
true,
BlazeClock.instance(),
BlazeClock.instance().nanoTime(),
- /* enabledCpuUsageProfiling= */ false);
+ /* enabledCpuUsageProfiling= */ false,
+ /* slimProfile= */ 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,7 +245,8 @@
true,
BlazeClock.instance(),
BlazeClock.instance().nanoTime(),
- /* enabledCpuUsageProfiling= */ false);
+ /* enabledCpuUsageProfiling= */ false,
+ /* slimProfile= */ false);
profiler.logSimpleTask(10000, 20000, ProfilerTask.VFS_STAT, "stat");
profiler.logSimpleTask(20000, 30000, ProfilerTask.REMOTE_EXECUTION, "remote execution");
@@ -351,7 +355,8 @@
true,
BlazeClock.instance(),
BlazeClock.instance().nanoTime(),
- /* enabledCpuUsageProfiling= */ false);
+ /* enabledCpuUsageProfiling= */ false,
+ /* slimProfile= */ false);
profiler.logSimpleTask(10000, 20000, ProfilerTask.VFS_STAT, "stat");
assertThat(ProfilerTask.VFS_STAT.collectsSlowestInstances()).isTrue();
@@ -571,7 +576,8 @@
false,
badClock,
initialNanoTime,
- /* enabledCpuUsageProfiling= */ false);
+ /* enabledCpuUsageProfiling= */ false,
+ /* slimProfile= */ false);
profiler.logSimpleTask(badClock.nanoTime(), ProfilerTask.INFO, "some task");
profiler.stop();
}
@@ -622,7 +628,8 @@
false,
BlazeClock.instance(),
BlazeClock.instance().nanoTime(),
- /* enabledCpuUsageProfiling= */ false);
+ /* enabledCpuUsageProfiling= */ false,
+ /* slimProfile= */ false);
profiler.logSimpleTaskDuration(
Profiler.nanoTimeMaybe(), Duration.ofSeconds(10), ProfilerTask.INFO, "foo");
try {
@@ -649,7 +656,8 @@
false,
BlazeClock.instance(),
BlazeClock.instance().nanoTime(),
- /* enabledCpuUsageProfiling= */ false);
+ /* enabledCpuUsageProfiling= */ false,
+ /* slimProfile= */ false);
profiler.logSimpleTaskDuration(
Profiler.nanoTimeMaybe(), Duration.ofSeconds(10), ProfilerTask.INFO, "foo");
try {
@@ -659,4 +667,50 @@
assertThat(expected).hasMessageThat().isEqualTo("Expected failure.");
}
}
+
+ private ByteArrayOutputStream getJsonProfileOutputStream(boolean slimProfile) throws IOException {
+ ByteArrayOutputStream outputStream = new ByteArrayOutputStream();
+ profiler.start(
+ getAllProfilerTasks(),
+ outputStream,
+ JSON_TRACE_FILE_FORMAT,
+ "basic test",
+ false,
+ BlazeClock.instance(),
+ BlazeClock.instance().nanoTime(),
+ /* enabledCpuUsageProfiling= */ false,
+ slimProfile);
+ long curTime = Profiler.nanoTimeMaybe();
+ for (int i = 0; i < 100_000; i++) {
+ Duration duration;
+ if (i % 100 == 0) {
+ duration = Duration.ofSeconds(1);
+ } else {
+ duration = Duration.ofMillis(i % 250);
+ }
+ profiler.logSimpleTaskDuration(curTime, duration, ProfilerTask.INFO, "foo");
+ curTime += duration.toNanos();
+ }
+ profiler.stop();
+ return outputStream;
+ }
+
+ @Test
+ public void testSlimProfileSize() throws Exception {
+ ByteArrayOutputStream fatOutputStream = getJsonProfileOutputStream(/* slimProfile= */ false);
+ String fatOutput = fatOutputStream.toString();
+ assertThat(fatOutput).doesNotContain("merged");
+
+ ByteArrayOutputStream slimOutputStream = getJsonProfileOutputStream(/* slimProfile= */ true);
+ String slimOutput = slimOutputStream.toString();
+ assertThat(slimOutput).contains("merged");
+
+ long fatProfileLen = fatOutputStream.size();
+ long slimProfileLen = slimOutputStream.size();
+ assertThat(fatProfileLen).isAtLeast(8 * slimProfileLen);
+
+ long fatProfileLineCount = fatOutput.split("\n").length;
+ long slimProfileLineCount = slimOutput.split("\n").length;
+ assertThat(fatProfileLineCount).isAtLeast(8 * slimProfileLineCount);
+ }
}
