Decorate critical path spans with target label, configuration, and primary output (if requested). Fixes https://github.com/bazelbuild/bazel/issues/24580 PiperOrigin-RevId: 971761533 Change-Id: I2827e34022a01e6a5cfb0f9fc26800085ad80172
diff --git a/src/main/java/com/google/devtools/build/lib/metrics/criticalpath/CriticalPathComponent.java b/src/main/java/com/google/devtools/build/lib/metrics/criticalpath/CriticalPathComponent.java index 8a6a98b..b4bb057 100644 --- a/src/main/java/com/google/devtools/build/lib/metrics/criticalpath/CriticalPathComponent.java +++ b/src/main/java/com/google/devtools/build/lib/metrics/criticalpath/CriticalPathComponent.java
@@ -171,6 +171,31 @@ return action.getMnemonic(); } + @Nullable + public String getPrimaryOutputExecPathString() { + return primaryOutput != null ? primaryOutput.getExecPathString() : null; + } + + public String getOwnerLabelAsString() { + ActionOwner owner = action.getOwner(); + if (owner == null) { + return ""; + } + Label ownerLabel = owner.getLabel(); + if (ownerLabel == null) { + return ""; + } + return ownerLabel.getCanonicalForm(); + } + + public String getOwnerConfigurationAsString() { + ActionOwner owner = action.getOwner(); + if (owner == null) { + return ""; + } + return owner.getConfigurationChecksum(); + } + /** An unique identifier of the component for one build execution */ public int getId() { return id;
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 fa567e2..6eeef37 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
@@ -157,6 +157,29 @@ } @Override + public void logActionTaskDuration( + long startTimeNanos, + Duration duration, + ProfilerTask type, + String description, + String mnemonic, + String primaryOutput, + String targetLabel, + String configuration) { + if (traceProfilerService != null) { + traceProfilerService.logActionTaskDuration( + startTimeNanos, + duration, + type, + description, + mnemonic, + primaryOutput, + targetLabel, + configuration); + } + } + + @Override public void logEventAtTime(long atTimeNanos, ProfilerTask type, String description) { if (traceProfilerService != null) { traceProfilerService.logEventAtTime(atTimeNanos, type, description);
diff --git a/src/main/java/com/google/devtools/build/lib/profiler/TaskData.java b/src/main/java/com/google/devtools/build/lib/profiler/TaskData.java index 7157863..ecfa4a7 100644 --- a/src/main/java/com/google/devtools/build/lib/profiler/TaskData.java +++ b/src/main/java/com/google/devtools/build/lib/profiler/TaskData.java
@@ -88,16 +88,30 @@ } jsonWriter.name("pid").value(1); - if (this instanceof ActionTaskData actionTaskData) { - if (actionTaskData.primaryOutputPath != null) { - // Primary outputs are non-mergeable, thus incompatible with slim profiles. - jsonWriter.name("out").value(actionTaskData.primaryOutputPath); + if (this instanceof ActionTaskData actionTaskData && actionTaskData.primaryOutputPath != null) { + // Primary outputs are non-mergeable, thus incompatible with slim profiles. + jsonWriter.name("out").value(actionTaskData.primaryOutputPath); + } + + boolean isCriticalPath = type == ProfilerTask.CRITICAL_PATH_COMPONENT; + ActionTaskData actionTaskData = (this instanceof ActionTaskData data) ? data : null; + boolean hasActionArgs = + actionTaskData != null + && (actionTaskData.targetLabel != null + || actionTaskData.mnemonic != null + || actionTaskData.configuration != null); + + // Chrome Trace Format allows only a single "args" object per trace event. + // Critical path events record their original execution thread ID in "args.tid", + // while action events record target label, mnemonic, and configuration hash in "args". + // Merge them into a single "args" object when either is present. + if (isCriticalPath || hasActionArgs) { + jsonWriter.name("args"); + jsonWriter.beginObject(); + if (isCriticalPath) { + jsonWriter.name("tid").value(threadId); } - if (actionTaskData.targetLabel != null - || actionTaskData.mnemonic != null - || actionTaskData.configuration != null) { - jsonWriter.name("args"); - jsonWriter.beginObject(); + if (hasActionArgs) { if (actionTaskData.targetLabel != null) { jsonWriter.name("target").value(actionTaskData.targetLabel); } @@ -107,13 +121,7 @@ if (actionTaskData.configuration != null) { jsonWriter.name("configuration").value(actionTaskData.configuration); } - jsonWriter.endObject(); } - } - if (type == ProfilerTask.CRITICAL_PATH_COMPONENT) { - jsonWriter.name("args"); - jsonWriter.beginObject(); - jsonWriter.name("tid").value(threadId); jsonWriter.endObject(); } jsonWriter @@ -127,8 +135,8 @@ /** * Similar to TaskData, specific for profiled actions. Depending on options, adds additional - * action specific information such as primary output path and target label. This is only meant to - * be used for ProfilerTask.ACTION. + * action specific information such as primary output path and target label. This is meant to be + * used for ProfilerTask.ACTION and ProfilerTask.CRITICAL_PATH_COMPONENT. */ static final class ActionTaskData extends TaskData { @Nullable final String primaryOutputPath;
diff --git a/src/main/java/com/google/devtools/build/lib/profiler/TraceProfilerService.java b/src/main/java/com/google/devtools/build/lib/profiler/TraceProfilerService.java index 1475519..7dd9c96 100644 --- a/src/main/java/com/google/devtools/build/lib/profiler/TraceProfilerService.java +++ b/src/main/java/com/google/devtools/build/lib/profiler/TraceProfilerService.java
@@ -152,6 +152,23 @@ void logSimpleTaskDuration( long startTimeNanos, Duration duration, ProfilerTask type, String description); + /** + * Similar to logSimpleTaskDuration, specific for action-related tasks (such as ACTION or + * CRITICAL_PATH_COMPONENT) that have additional information such as primary output path and + * target label. + */ + default void logActionTaskDuration( + long startTimeNanos, + Duration duration, + ProfilerTask type, + String description, + String mnemonic, + String primaryOutput, + String targetLabel, + String configuration) { + logSimpleTaskDuration(startTimeNanos, duration, type, description); + } + /** Used to log "events" happening at a specific time - tasks with zero duration. */ void logEventAtTime(long atTimeNanos, ProfilerTask type, String description);
diff --git a/src/main/java/com/google/devtools/build/lib/profiler/TraceProfilerServiceImpl.java b/src/main/java/com/google/devtools/build/lib/profiler/TraceProfilerServiceImpl.java index 4e255e8..fd3db22 100644 --- a/src/main/java/com/google/devtools/build/lib/profiler/TraceProfilerServiceImpl.java +++ b/src/main/java/com/google/devtools/build/lib/profiler/TraceProfilerServiceImpl.java
@@ -511,6 +511,59 @@ } } + private void logActionTask( + long startTimeNanos, + long duration, + ProfilerTask type, + String description, + String mnemonic, + @Nullable String primaryOutput, + @Nullable String targetLabel, + @Nullable String configuration) { + var lane = borrowLane(); + try { + checkNotNull(description); + checkState(!description.isEmpty(), "No description -> not helpful"); + if (duration < 0) { + // See note in Clock#nanoTime, which is used by Profiler#nanoTimeMaybe. + duration = 0; + } + + StatRecorder statRecorder = tasksHistograms[type.ordinal()]; + if (collectTaskHistograms && statRecorder != null) { + statRecorder.addStat((int) Duration.ofNanos(duration).toMillis(), description); + } + + if (isActive() && startTimeNanos >= 0 && isProfiling(type)) { + JsonTraceFileWriter currentWriter = writerRef.get(); + if (wasTaskSlowEnoughToRecord(type, duration)) { + TaskData data = + new ActionTaskData( + getLaneId(lane), + startTimeNanos, + duration, + type, + mnemonic, + description, + primaryOutput, + targetLabel, + configuration); + if (currentWriter != null) { + currentWriter.enqueue(data); + } + + SlowestTaskAggregator aggregator = slowestTasks[type.ordinal()]; + + if (aggregator != null) { + aggregator.add(data); + } + } + } + } finally { + releaseLane(lane); + } + } + @Override public void logSimpleTask(long startTimeNanos, ProfilerTask type, String description) { if (clock != null) { @@ -531,6 +584,27 @@ } @Override + public void logActionTaskDuration( + long startTimeNanos, + Duration duration, + ProfilerTask type, + String description, + String mnemonic, + String primaryOutput, + String targetLabel, + String configuration) { + logActionTask( + startTimeNanos, + duration.toNanos(), + type, + description, + mnemonic, + includePrimaryOutput ? primaryOutput : null, + includeTargetLabel ? targetLabel : null, + includeConfiguration ? configuration : null); + } + + @Override public void logEventAtTime(long atTimeNanos, ProfilerTask type, String description) { logTask(atTimeNanos, 0, type, description); }
diff --git a/src/main/java/com/google/devtools/build/lib/runtime/BuildSummaryStatsModule.java b/src/main/java/com/google/devtools/build/lib/runtime/BuildSummaryStatsModule.java index 25c7bdb..7184724 100644 --- a/src/main/java/com/google/devtools/build/lib/runtime/BuildSummaryStatsModule.java +++ b/src/main/java/com/google/devtools/build/lib/runtime/BuildSummaryStatsModule.java
@@ -185,11 +185,15 @@ // way. for (CriticalPathComponent stat : criticalPath.components().reverse()) { Profiler.instance() - .logSimpleTaskDuration( + .logActionTaskDuration( stat.getStartTimeNanos(), stat.getElapsedTime(), ProfilerTask.CRITICAL_PATH_COMPONENT, - stat.prettyPrintAction()); + stat.prettyPrintAction(), + stat.getMnemonic(), + stat.getPrimaryOutputExecPathString(), + stat.getOwnerLabelAsString(), + stat.getOwnerConfigurationAsString()); } } }
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 3f3b980..8b08dc7 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
@@ -349,8 +349,8 @@ documentationCategory = OptionDocumentationCategory.LOGGING, effectTags = {OptionEffectTag.BAZEL_MONITORING}, help = - "Includes the extra \"out\" attribute in action events that contains the exec path " - + "to the action's primary output.") + "Includes the extra \"out\" attribute in action and critical-path events that contains" + + " the exec path to the action's primary output.") public abstract boolean getIncludePrimaryOutput(); @Option( @@ -358,7 +358,7 @@ defaultValue = "false", documentationCategory = OptionDocumentationCategory.LOGGING, effectTags = {OptionEffectTag.BAZEL_MONITORING}, - help = "Includes target label in action events' JSON profile data.") + help = "Includes target label in action and critical-path events' JSON profile data.") public abstract boolean getProfileIncludeTargetLabel(); @Option( @@ -366,7 +366,9 @@ defaultValue = "false", documentationCategory = OptionDocumentationCategory.LOGGING, effectTags = {OptionEffectTag.BAZEL_MONITORING}, - help = "Includes target configuration hash in action events' JSON profile data.") + help = + "Includes target configuration hash in action and critical-path events' JSON profile" + + " data.") public abstract boolean getProfileIncludeTargetConfiguration(); @Option(
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 62e2898..caa529c 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
@@ -41,6 +41,7 @@ import java.time.Instant; import java.util.ArrayList; import java.util.List; +import java.util.Objects; import java.util.UUID; import java.util.concurrent.CountDownLatch; import java.util.concurrent.Executors; @@ -934,6 +935,170 @@ .hasSize(1); } + @Test + public void testPrimaryOutputForCriticalPath() throws Exception { + ByteArrayOutputStream buffer = new ByteArrayOutputStream(); + + profiler.start( + getAllProfilerTasks(), + buffer, + JSON_TRACE_FILE_FORMAT, + "dummy_output_base", + UUID.randomUUID(), + true, + clock, + clock.nanoTime(), + /* slimProfile= */ false, + /* slimProfileSizeLimit= */ -1, + /* includePrimaryOutput= */ true, + /* includeTargetLabel= */ false, + /* includeConfiguration= */ false, + /* collectTaskHistograms= */ true); + profiler.logActionTaskDuration( + clock.nanoTime(), + Duration.ofMillis(10), + ProfilerTask.CRITICAL_PATH_COMPONENT, + "test", + /* mnemonic= */ null, + "foo.out", + "//foo:bar", + /* configuration= */ null); + profiler.stop(); + + JsonProfile jsonProfile = new JsonProfile(new ByteArrayInputStream(buffer.toByteArray())); + + assertThat( + jsonProfile.getTraceEvents().stream() + .filter(traceEvent -> Objects.equals(traceEvent.primaryOutputPath(), "foo.out"))) + .hasSize(1); + } + + @Test + public void testTargetLabelForCriticalPath() throws Exception { + ByteArrayOutputStream buffer = new ByteArrayOutputStream(); + + profiler.start( + getAllProfilerTasks(), + buffer, + JSON_TRACE_FILE_FORMAT, + "dummy_output_base", + UUID.randomUUID(), + true, + clock, + clock.nanoTime(), + /* slimProfile= */ false, + /* slimProfileSizeLimit= */ -1, + /* includePrimaryOutput= */ false, + /* includeTargetLabel= */ true, + /* includeConfiguration= */ false, + /* collectTaskHistograms= */ true); + profiler.logActionTaskDuration( + clock.nanoTime(), + Duration.ofMillis(10), + ProfilerTask.CRITICAL_PATH_COMPONENT, + "test", + /* mnemonic= */ null, + "foo.out", + "//foo:bar", + /* configuration= */ null); + profiler.stop(); + + JsonProfile jsonProfile = new JsonProfile(new ByteArrayInputStream(buffer.toByteArray())); + + assertThat( + jsonProfile.getTraceEvents().stream() + .filter(traceEvent -> Objects.equals(traceEvent.targetLabel(), "//foo:bar"))) + .hasSize(1); + } + + @Test + public void testTargetConfigurationForCriticalPath() throws Exception { + ByteArrayOutputStream buffer = new ByteArrayOutputStream(); + + profiler.start( + getAllProfilerTasks(), + buffer, + JSON_TRACE_FILE_FORMAT, + "dummy_output_base", + UUID.randomUUID(), + true, + clock, + clock.nanoTime(), + /* slimProfile= */ false, + /* slimProfileSizeLimit= */ -1, + /* includePrimaryOutput= */ false, + /* includeTargetLabel= */ false, + /* includeConfiguration= */ true, + /* collectTaskHistograms= */ true); + profiler.logActionTaskDuration( + clock.nanoTime(), + Duration.ofMillis(10), + ProfilerTask.CRITICAL_PATH_COMPONENT, + "test", + /* mnemonic= */ null, + "foo.out", + "//foo:bar", + "012345"); + profiler.stop(); + + JsonProfile jsonProfile = new JsonProfile(new ByteArrayInputStream(buffer.toByteArray())); + + assertThat( + jsonProfile.getTraceEvents().stream() + .filter(traceEvent -> Objects.equals(traceEvent.configuration(), "012345"))) + .hasSize(1); + } + + @Test + public void testCriticalPathAllActionPropertiesAndTid() throws Exception { + ByteArrayOutputStream buffer = new ByteArrayOutputStream(); + + profiler.start( + getAllProfilerTasks(), + buffer, + JSON_TRACE_FILE_FORMAT, + "dummy_output_base", + UUID.randomUUID(), + true, + clock, + clock.nanoTime(), + /* slimProfile= */ false, + /* slimProfileSizeLimit= */ -1, + /* includePrimaryOutput= */ true, + /* includeTargetLabel= */ true, + /* includeConfiguration= */ true, + /* collectTaskHistograms= */ true); + profiler.logActionTaskDuration( + clock.nanoTime(), + Duration.ofMillis(10), + ProfilerTask.CRITICAL_PATH_COMPONENT, + "action description", + "CppCompile", + "foo.out", + "//foo:bar", + "012345"); + profiler.stop(); + + JsonProfile jsonProfile = new JsonProfile(new ByteArrayInputStream(buffer.toByteArray())); + List<TraceEvent> traceEvents = + jsonProfile.getTraceEvents().stream() + .filter(traceEvent -> Objects.equals(traceEvent.category(), "critical path component")) + .toList(); + + assertThat(traceEvents).hasSize(1); + TraceEvent event = traceEvents.get(0); + assertThat(event.primaryOutputPath()).isEqualTo("foo.out"); + assertThat(event.targetLabel()).isEqualTo("//foo:bar"); + assertThat(event.mnemonic()).isEqualTo("CppCompile"); + assertThat(event.configuration()).isEqualTo("012345"); + assertThat(event.threadId()).isEqualTo(ThreadMetadata.CRITICAL_PATH_THREAD_ID); + assertThat(event.args()).isNotNull(); + assertThat(event.args().get("tid")).isNotNull(); + assertThat(event.args().get("target")).isEqualTo("//foo:bar"); + assertThat(event.args().get("mnemonic")).isEqualTo("CppCompile"); + assertThat(event.args().get("configuration")).isEqualTo("012345"); + } + private ByteArrayOutputStream getJsonProfileOutputStream(SlimProfileConfiguration slimProfile) throws IOException { ByteArrayOutputStream outputStream = new ByteArrayOutputStream();