[Profiler] Add target label of action owner to profiler trace files
While analyzing trace files, it is useful to have target label associated with the action which was created by that target. This change adds target label under trace events which have owner, mostly Action-type event. Target label is saved as a custom entry to "args" map attached to each Action event, as per trace format definition.
The change is guarded by new flag `--experimental_profile_include_target_label`
Closes #11443.
PiperOrigin-RevId: 314687980
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 bfc7f84..ae4543c0 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
@@ -165,15 +165,18 @@
private static final class ActionTaskData extends TaskData {
final String primaryOutputPath;
+ final String targetLabel;
ActionTaskData(
int id,
long startTimeNanos,
ProfilerTask eventType,
String description,
- String primaryOutputPath) {
+ String primaryOutputPath,
+ String targetLabel) {
super(id, startTimeNanos, eventType, description);
this.primaryOutputPath = primaryOutputPath;
+ this.targetLabel = targetLabel;
}
}
@@ -370,7 +373,8 @@
long execStartTimeNanos,
boolean enabledCpuUsageProfiling,
boolean slimProfile,
- boolean includePrimaryOutput)
+ boolean includePrimaryOutput,
+ boolean includeTargetLabel)
throws IOException {
Preconditions.checkState(!isActive(), "Profiler already active");
initHistograms();
@@ -401,7 +405,8 @@
slimProfile,
outputBase,
buildID,
- includePrimaryOutput);
+ includePrimaryOutput,
+ includeTargetLabel);
break;
case JSON_TRACE_FILE_COMPRESSED_FORMAT:
writer =
@@ -411,7 +416,8 @@
slimProfile,
outputBase,
buildID,
- includePrimaryOutput);
+ includePrimaryOutput,
+ includeTargetLabel);
}
writer.start();
}
@@ -670,14 +676,19 @@
* primaryOutput.
*/
public SilentCloseable profileAction(
- ProfilerTask type, String description, String primaryOutput) {
+ ProfilerTask type, String description, String primaryOutput, String targetLabel) {
Preconditions.checkNotNull(description);
if (isActive() && isProfiling(type)) {
taskStack
.get()
.push(
new ActionTaskData(
- taskId.incrementAndGet(), clock.nanoTime(), type, description, primaryOutput));
+ taskId.incrementAndGet(),
+ clock.nanoTime(),
+ type,
+ description,
+ primaryOutput,
+ targetLabel));
return () -> completeTask(type);
} else {
return NOP;
@@ -805,6 +816,7 @@
ThreadLocal.withInitial(() -> Boolean.FALSE);
private final boolean slimProfile;
private final boolean includePrimaryOutput;
+ private final boolean includeTargetLabel;
private final UUID buildID;
private final String outputBase;
@@ -821,13 +833,15 @@
boolean slimProfile,
String outputBase,
UUID buildID,
- boolean includePrimaryOutput) {
+ boolean includePrimaryOutput,
+ boolean includeTargetLabel) {
this.outStream = outStream;
this.profileStartTimeNanos = profileStartTimeNanos;
this.slimProfile = slimProfile;
this.buildID = buildID;
this.outputBase = outputBase;
this.includePrimaryOutput = includePrimaryOutput;
+ this.includeTargetLabel = includeTargetLabel;
}
@Override
@@ -932,6 +946,12 @@
if (includePrimaryOutput && data instanceof ActionTaskData) {
writer.name("out").value(((ActionTaskData) data).primaryOutputPath);
}
+ if (includeTargetLabel && data instanceof ActionTaskData) {
+ writer.name("args");
+ writer.beginObject();
+ writer.name("target").value(((ActionTaskData) data).targetLabel);
+ writer.endObject();
+ }
long threadId =
data.type == ProfilerTask.CRITICAL_PATH_COMPONENT
? CRITICAL_PATH_THREAD_ID
diff --git a/src/main/java/com/google/devtools/build/lib/profiler/TraceEvent.java b/src/main/java/com/google/devtools/build/lib/profiler/TraceEvent.java
index 00c66cd..283d939 100644
--- a/src/main/java/com/google/devtools/build/lib/profiler/TraceEvent.java
+++ b/src/main/java/com/google/devtools/build/lib/profiler/TraceEvent.java
@@ -15,7 +15,10 @@
package com.google.devtools.build.lib.profiler;
import com.google.auto.value.AutoValue;
+import com.google.common.collect.ImmutableList;
+import com.google.common.collect.ImmutableMap;
import com.google.gson.stream.JsonReader;
+import com.google.gson.stream.JsonToken;
import java.io.IOException;
import java.time.Duration;
import java.util.ArrayList;
@@ -36,9 +39,10 @@
@Nullable Duration timestamp,
@Nullable Duration duration,
long threadId,
- @Nullable String primaryOutputPath) {
+ @Nullable String primaryOutputPath,
+ @Nullable String targetLabel) {
return new AutoValue_TraceEvent(
- category, name, timestamp, duration, threadId, primaryOutputPath);
+ category, name, timestamp, duration, threadId, primaryOutputPath, targetLabel);
}
@Nullable
@@ -58,6 +62,9 @@
@Nullable
public abstract String primaryOutputPath();
+ @Nullable
+ public abstract String targetLabel();
+
private static TraceEvent createFromJsonReader(JsonReader reader) throws IOException {
String category = null;
String name = null;
@@ -65,6 +72,7 @@
Duration duration = null;
long threadId = -1;
String primaryOutputPath = null;
+ String targetLabel = null;
reader.beginObject();
while (reader.hasNext()) {
@@ -88,12 +96,67 @@
case "out":
primaryOutputPath = reader.nextString();
break;
+ case "args":
+ ImmutableMap<String, Object> args = parseMap(reader);
+ Object target = args.get("target");
+ targetLabel = target instanceof String ? (String) target : null;
+ break;
default:
reader.skipValue();
}
}
reader.endObject();
- return TraceEvent.create(category, name, timestamp, duration, threadId, primaryOutputPath);
+ return TraceEvent.create(
+ category, name, timestamp, duration, threadId, primaryOutputPath, targetLabel);
+ }
+
+ private static ImmutableMap<String, Object> parseMap(JsonReader reader) throws IOException {
+ ImmutableMap.Builder<String, Object> builder = ImmutableMap.builder();
+
+ reader.beginObject();
+ while (reader.peek() != JsonToken.END_OBJECT) {
+ String name = reader.nextName();
+ Object val = parseSingleValueRecursively(reader);
+ builder.put(name, val);
+ }
+ reader.endObject();
+
+ return builder.build();
+ }
+
+ private static ImmutableList<Object> parseArray(JsonReader reader) throws IOException {
+ ImmutableList.Builder<Object> builder = ImmutableList.builder();
+
+ reader.beginArray();
+ while (reader.peek() != JsonToken.END_ARRAY) {
+ Object val = parseSingleValueRecursively(reader);
+ builder.add(val);
+ }
+ reader.endArray();
+
+ return builder.build();
+ }
+
+ private static Object parseSingleValueRecursively(JsonReader reader) throws IOException {
+ JsonToken nextToken = reader.peek();
+ switch (nextToken) {
+ case BOOLEAN:
+ return reader.nextBoolean();
+ case NULL:
+ reader.nextNull();
+ return null;
+ case NUMBER:
+ // Json's only numeric type is number, using Double to accommodate all types
+ return reader.nextDouble();
+ case STRING:
+ return reader.nextString();
+ case BEGIN_OBJECT:
+ return parseMap(reader);
+ case BEGIN_ARRAY:
+ return parseArray(reader);
+ default:
+ throw new IOException("Unexpected token " + nextToken.name());
+ }
}
public static List<TraceEvent> parseTraceEvents(JsonReader reader) throws IOException {
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 fecb07a..fec568b 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
@@ -391,7 +391,8 @@
execStartTimeNanos,
options.enableCpuUsageProfiling,
options.slimProfile,
- options.includePrimaryOutput);
+ options.includePrimaryOutput,
+ options.profileIncludeTargetLabel);
// 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 e1ae2a7..765a4f5 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
@@ -289,6 +289,14 @@
public boolean includePrimaryOutput;
@Option(
+ name = "experimental_profile_include_target_label",
+ defaultValue = "false",
+ documentationCategory = OptionDocumentationCategory.LOGGING,
+ effectTags = {OptionEffectTag.AFFECTS_OUTPUTS, OptionEffectTag.BAZEL_MONITORING},
+ help = "Includes target label in action events' JSON profile data.")
+ public boolean profileIncludeTargetLabel;
+
+ @Option(
name = "experimental_announce_profile_path",
defaultValue = "false",
documentationCategory = OptionDocumentationCategory.LOGGING,
diff --git a/src/main/java/com/google/devtools/build/lib/skyframe/SkyframeActionExecutor.java b/src/main/java/com/google/devtools/build/lib/skyframe/SkyframeActionExecutor.java
index 5beb3dd..5ca7f6c 100644
--- a/src/main/java/com/google/devtools/build/lib/skyframe/SkyframeActionExecutor.java
+++ b/src/main/java/com/google/devtools/build/lib/skyframe/SkyframeActionExecutor.java
@@ -44,6 +44,7 @@
import com.google.devtools.build.lib.actions.ActionLogBufferPathGenerator;
import com.google.devtools.build.lib.actions.ActionLookupData;
import com.google.devtools.build.lib.actions.ActionMiddlemanEvent;
+import com.google.devtools.build.lib.actions.ActionOwner;
import com.google.devtools.build.lib.actions.ActionResult;
import com.google.devtools.build.lib.actions.ActionResultReceivedEvent;
import com.google.devtools.build.lib.actions.ActionScanningCompletedEvent;
@@ -828,7 +829,8 @@
profiler.profileAction(
ProfilerTask.ACTION,
action.describe(),
- action.getPrimaryOutput().getExecPathString())) {
+ action.getPrimaryOutput().getExecPathString(),
+ getOwnerLabelAsString(action))) {
String message = action.getProgressMessage();
if (message != null) {
reporter.startTask(null, prependExecPhaseStats(message));
@@ -897,6 +899,18 @@
}
}
+ private String getOwnerLabelAsString(Action action) {
+ ActionOwner owner = action.getOwner();
+ if (owner == null) {
+ return "";
+ }
+ Label ownerLabel = owner.getLabel();
+ if (ownerLabel == null) {
+ return "";
+ }
+ return ownerLabel.getCanonicalForm();
+ }
+
private void notifyActionCompletion(
ExtendedEventHandler eventHandler, boolean postActionCompletionEvent) {
statusReporter.remove(action);
diff --git a/src/test/java/com/google/devtools/build/lib/buildtool/util/BlazeRuntimeWrapper.java b/src/test/java/com/google/devtools/build/lib/buildtool/util/BlazeRuntimeWrapper.java
index 826e3e3..469668a 100644
--- a/src/test/java/com/google/devtools/build/lib/buildtool/util/BlazeRuntimeWrapper.java
+++ b/src/test/java/com/google/devtools/build/lib/buildtool/util/BlazeRuntimeWrapper.java
@@ -291,7 +291,8 @@
/* execStartTimeNanos= */ 42,
/* enabledCpuUsageProfiling= */ false,
/* slimProfile= */ false,
- /* includePrimaryOutput= */ false);
+ /* includePrimaryOutput= */ false,
+ /* includeTargetLabel= */ false);
OutErr outErr = env.getReporter().getOutErr();
System.setOut(new PrintStream(outErr.getOutputStream(), /*autoflush=*/ true));
System.setErr(new PrintStream(outErr.getErrorStream(), /*autoflush=*/ true));
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 5a880be..e5f3c21 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
@@ -40,7 +40,8 @@
BlazeClock.instance().nanoTime(),
/* enabledCpuUsageProfiling= */ false,
/* slimProfile= */ false,
- /* includePrimaryOutput= */ false);
+ /* includePrimaryOutput= */ false,
+ /* includeTargetLabel= */ false);
}
@BeforeExperiment
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 f6ee52e..616476c 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
@@ -94,7 +94,8 @@
BlazeClock.nanoTime(),
/* enabledCpuUsageProfiling= */ false,
/* slimProfile= */ false,
- /* includePrimaryOutput= */ false);
+ /* includePrimaryOutput= */ false,
+ /* includeTargetLabel= */ false);
return buffer;
}
@@ -110,7 +111,8 @@
BlazeClock.nanoTime(),
/* enabledCpuUsageProfiling= */ false,
/* slimProfile= */ false,
- /* includePrimaryOutput= */ false);
+ /* includePrimaryOutput= */ false,
+ /* includeTargetLabel= */ false);
}
@Test
@@ -207,7 +209,8 @@
clock.nanoTime(),
/* enabledCpuUsageProfiling= */ false,
/* slimProfile= */ false,
- /* includePrimaryOutput= */ false);
+ /* includePrimaryOutput= */ false,
+ /* includeTargetLabel= */ false);
try (SilentCloseable c = profiler.profile(ProfilerTask.ACTION, "action task")) {
// Next task takes less than 10 ms but should be recorded anyway.
long before = clock.nanoTime();
@@ -252,7 +255,8 @@
BlazeClock.instance().nanoTime(),
/* enabledCpuUsageProfiling= */ false,
/* slimProfile= */ false,
- /* includePrimaryOutput= */ false);
+ /* includePrimaryOutput= */ false,
+ /* includeTargetLabel= */ false);
profiler.logSimpleTask(10000, 20000, ProfilerTask.VFS_STAT, "stat");
// Unlike the VFS_STAT event above, the remote execution event will not be recorded since we
// don't record the slowest remote exec events (see ProfilerTask.java).
@@ -368,7 +372,8 @@
BlazeClock.instance().nanoTime(),
/* enabledCpuUsageProfiling= */ false,
/* slimProfile= */ false,
- /* includePrimaryOutput= */ false);
+ /* includePrimaryOutput= */ false,
+ /* includeTargetLabel= */ false);
profiler.logSimpleTask(10000, 20000, ProfilerTask.VFS_STAT, "stat");
assertThat(ProfilerTask.VFS_STAT.collectsSlowestInstances()).isTrue();
@@ -549,7 +554,8 @@
initialNanoTime,
/* enabledCpuUsageProfiling= */ false,
/* slimProfile= */ false,
- /* includePrimaryOutput= */ false);
+ /* includePrimaryOutput= */ false,
+ /* includeTargetLabel= */ false);
profiler.logSimpleTask(badClock.nanoTime(), ProfilerTask.INFO, "some task");
profiler.stop();
}
@@ -603,7 +609,8 @@
BlazeClock.instance().nanoTime(),
/* enabledCpuUsageProfiling= */ false,
/* slimProfile= */ false,
- /* includePrimaryOutput= */ false);
+ /* includePrimaryOutput= */ false,
+ /* includeTargetLabel= */ false);
profiler.logSimpleTaskDuration(
Profiler.nanoTimeMaybe(), Duration.ofSeconds(10), ProfilerTask.INFO, "foo");
IOException expected = assertThrows(IOException.class, () -> profiler.stop());
@@ -629,7 +636,8 @@
BlazeClock.instance().nanoTime(),
/* enabledCpuUsageProfiling= */ false,
/* slimProfile= */ false,
- /* includePrimaryOutput= */ false);
+ /* includePrimaryOutput= */ false,
+ /* includeTargetLabel= */ false);
profiler.logSimpleTaskDuration(
Profiler.nanoTimeMaybe(), Duration.ofSeconds(10), ProfilerTask.INFO, "foo");
IOException expected = assertThrows(IOException.class, () -> profiler.stop());
@@ -651,8 +659,9 @@
clock.nanoTime(),
/* enabledCpuUsageProfiling= */ false,
/* slimProfile= */ false,
- /* includePrimaryOutput= */ true);
- try (SilentCloseable c = profiler.profileAction(ProfilerTask.ACTION, "test", "foo.out")) {
+ /* includePrimaryOutput= */ true,
+ /* includeTargetLabel= */ false);
+ try (SilentCloseable c = profiler.profileAction(ProfilerTask.ACTION, "test", "foo.out", "")) {
profiler.logEvent(ProfilerTask.PHASE, "event1");
}
profiler.stop();
@@ -666,6 +675,38 @@
.hasSize(1);
}
+ @Test
+ public void testTargetLabelForAction() throws Exception {
+ ByteArrayOutputStream buffer = new ByteArrayOutputStream();
+
+ profiler.start(
+ getAllProfilerTasks(),
+ buffer,
+ JSON_TRACE_FILE_FORMAT,
+ "dummy_output_base",
+ UUID.randomUUID(),
+ true,
+ clock,
+ clock.nanoTime(),
+ /* enabledCpuUsageProfiling= */ false,
+ /* slimProfile= */ false,
+ /* includePrimaryOutput= */ false,
+ /* includeTargetLabel= */ true);
+ try (SilentCloseable c =
+ profiler.profileAction(ProfilerTask.ACTION, "test", "foo.out", "//foo:bar")) {
+ profiler.logEvent(ProfilerTask.PHASE, "event1");
+ }
+ profiler.stop();
+
+ JsonProfile jsonProfile = new JsonProfile(new ByteArrayInputStream(buffer.toByteArray()));
+
+ assertThat(
+ jsonProfile.getTraceEvents().stream()
+ .filter(traceEvent -> "//foo:bar".equals(traceEvent.targetLabel()))
+ .collect(Collectors.toList()))
+ .hasSize(1);
+ }
+
private ByteArrayOutputStream getJsonProfileOutputStream(boolean slimProfile) throws IOException {
ByteArrayOutputStream outputStream = new ByteArrayOutputStream();
profiler.start(
@@ -679,7 +720,8 @@
BlazeClock.instance().nanoTime(),
/* enabledCpuUsageProfiling= */ false,
slimProfile,
- /* includePrimaryOutput= */ false);
+ /* includePrimaryOutput= */ false,
+ /* includeTargetLabel= */ false);
long curTime = Profiler.nanoTimeMaybe();
for (int i = 0; i < 100_000; i++) {
Duration duration;
