From 6e945e8ab422ca0a195d09899cce61ba6c0cfa59 Mon Sep 17 00:00:00 2001 From: Googler Date: Thu, 10 Nov 2022 14:47:21 -0800 Subject: [PATCH] Treat `DEBUG` events as progress-like. The primary source of `DEBUG` events is the starlark `print()` function. The motivation in making this change is to emit `print()` statements more intelligibly, including: * Not deduplicating multiple identical prints from the same line of code. * Not replaying prints when the corresponding skyframe node is cached. For example, we currently replay prints in a `BUILD` file even when the package is up to date and the starlark code is not executed. A secondary benefit is that we don't spend memory retaining `DEBUG` events in skyframe. This change makes `DEBUG` events match the semantics of `INFO` and `PROGRESS` events. See the documentation on `Reportable#storeForReplay`. There is some chance that this causes additional spam or breaks something relying on cached print statements in incremental build output, but per [style guide](https://bazel.build/rules/bzl-style#print-for-debugging), `print()` should not be used for production code anyway. There are a couple other minor sources of `DEBUG` events besides `print()`, and those semantics will be changed as well (for the better, in my opinion). Fixes #16721. RELNOTES: Starlark `print()` statements are now emitted iff the line of code is executed. They are no longer replayed on subsequent invocations unless the Starlark code is re-executed. Additionally, multiple identical `print()` statements (same string from the same line of code, e.g. from a loop) are all emitted and no longer deduplicated. PiperOrigin-RevId: 487645012 Change-Id: I8b13df67febc9f330c864930688bca31c3711276 --- .../devtools/build/lib/events/Event.java | 2 +- .../devtools/build/lib/events/Reportable.java | 4 +-- .../lib/starlark/StarlarkIntegrationTest.java | 32 +++++++++++++++++++ ...configurations_external_workspaces_test.sh | 4 +++ .../starlark_configurations_test.sh | 2 ++ 5 files changed, 41 insertions(+), 3 deletions(-) diff --git a/src/main/java/com/google/devtools/build/lib/events/Event.java b/src/main/java/com/google/devtools/build/lib/events/Event.java index 34d7f57d5f158f..37684681e25196 100644 --- a/src/main/java/com/google/devtools/build/lib/events/Event.java +++ b/src/main/java/com/google/devtools/build/lib/events/Event.java @@ -73,7 +73,7 @@ public void reportTo(ExtendedEventHandler handler) { @Override public boolean storeForReplay() { - return kind != EventKind.PROGRESS && kind != EventKind.INFO; + return kind != EventKind.PROGRESS && kind != EventKind.INFO && kind != EventKind.DEBUG; } public EventKind getKind() { diff --git a/src/main/java/com/google/devtools/build/lib/events/Reportable.java b/src/main/java/com/google/devtools/build/lib/events/Reportable.java index e736f55c7b08d9..4601fc4ef172c1 100644 --- a/src/main/java/com/google/devtools/build/lib/events/Reportable.java +++ b/src/main/java/com/google/devtools/build/lib/events/Reportable.java @@ -42,8 +42,8 @@ public interface Reportable { * *

Evaluations may disable all event storage and replay by using a custom {@link * com.google.devtools.build.skyframe.EventFilter}, in which case this method is only used to - * fulfill the semantics of {@link - * com.google.devtools.build.skyframe.SkyFunction.Environment#reportEvent}. + * fulfill the semantics described at {@link + * com.google.devtools.build.skyframe.SkyFunction.Environment#getListener}. * *

This method is not relevant for events which do not originate from {@link * com.google.devtools.build.skyframe.SkyFunction} evaluation. diff --git a/src/test/java/com/google/devtools/build/lib/starlark/StarlarkIntegrationTest.java b/src/test/java/com/google/devtools/build/lib/starlark/StarlarkIntegrationTest.java index 0fad5fa2d6cb1e..49eef9661a1cad 100644 --- a/src/test/java/com/google/devtools/build/lib/starlark/StarlarkIntegrationTest.java +++ b/src/test/java/com/google/devtools/build/lib/starlark/StarlarkIntegrationTest.java @@ -3780,4 +3780,36 @@ public void nonExecutableStarlarkRuleReturningTestEnvironmentProducesAWarning() + " non-test target has no effect", ImmutableSet.of(EventKind.WARNING)); } + + @Test + public void identicalPrintStatementsOnSameLineNotDeduplicated_buildFileLoop() throws Exception { + scratch.file("foo/BUILD", "[print('this is a print statement') for _ in range(2)]"); + update("//foo:all", /*loadingPhaseThreads=*/ 1, /*doAnalysis=*/ false); + assertContainsEventWithFrequency("this is a print statement", 2); + } + + @Test + public void identicalPrintStatementsOnSameLineNotDeduplicated_macroCalledFromMultipleBuildFiles() + throws Exception { + scratch.file("defs/BUILD"); + scratch.file("defs/macro.bzl", "def macro():", " print('this is a print statement')"); + scratch.file("foo/BUILD", "load('//defs:macro.bzl', 'macro')", "macro()"); + scratch.file("bar/BUILD", "load('//defs:macro.bzl', 'macro')", "macro()"); + update("//...", /*loadingPhaseThreads=*/ 1, /*doAnalysis=*/ false); + assertContainsEventWithFrequency("this is a print statement", 2); + } + + @Test + public void identicalPrintStatementsOnSameLineNotDeduplicated_ruleImplementationFunction() + throws Exception { + scratch.file( + "foo/defs.bzl", + "def _my_rule_impl(ctx):", + " print('this is a print statement')", + "my_rule = rule(implementation = _my_rule_impl)"); + scratch.file( + "foo/BUILD", "load(':defs.bzl', 'my_rule')", "my_rule(name = 'a')", "my_rule(name = 'b')"); + update("//foo:all", /*loadingPhaseThreads=*/ 1, /*doAnalysis=*/ true); + assertContainsEventWithFrequency("this is a print statement", 2); + } } diff --git a/src/test/shell/integration/starlark_configurations_external_workspaces_test.sh b/src/test/shell/integration/starlark_configurations_external_workspaces_test.sh index 2eef587c768588..e09eaf752900a2 100755 --- a/src/test/shell/integration/starlark_configurations_external_workspaces_test.sh +++ b/src/test/shell/integration/starlark_configurations_external_workspaces_test.sh @@ -228,11 +228,15 @@ EOF expect_log "value before transition: prickly-pear" expect_log "value after transition: prickly-pear" + bazel clean 2>"$TEST_log" || fail "Clean failed" + bazel build :my_target --@sub//:my_flag=prickly-pear \ > output 2>"$TEST_log" || fail "Expected success" expect_log "value before transition: prickly-pear" expect_log "value after transition: prickly-pear" + bazel clean 2>"$TEST_log" || fail "Clean failed" + bazel build :my_target --@//:my_flag=prickly-pear \ > output 2>"$TEST_log" || fail "Expected success" expect_log "value before transition: prickly-pear" diff --git a/src/test/shell/integration/starlark_configurations_test.sh b/src/test/shell/integration/starlark_configurations_test.sh index 734a65d35e6196..fb83279483e2af 100755 --- a/src/test/shell/integration/starlark_configurations_test.sh +++ b/src/test/shell/integration/starlark_configurations_test.sh @@ -173,6 +173,8 @@ function test_multiple_starlark_flags() { expect_log "type=coffee" expect_log "temp=iced" + bazel clean 2>"$TEST_log" || fail "Clean failed" + # Ensure that order doesn't matter. bazel build //$pkg:my_drink --//$pkg:temp="iced" --//$pkg:type="coffee" \ > output 2>"$TEST_log" || fail "Expected success"