Skip to content

Commit

Permalink
Treat DEBUG events as progress-like.
Browse files Browse the repository at this point in the history
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
  • Loading branch information
justinhorvitz authored and copybara-github committed Nov 10, 2022
1 parent 6c77c5a commit 6e945e8
Show file tree
Hide file tree
Showing 5 changed files with 41 additions and 3 deletions.
Original file line number Diff line number Diff line change
Expand Up @@ -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() {
Expand Down
Original file line number Diff line number Diff line change
Expand Up @@ -42,8 +42,8 @@ public interface Reportable {
*
* <p>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}.
*
* <p>This method is not relevant for events which do not originate from {@link
* com.google.devtools.build.skyframe.SkyFunction} evaluation.
Expand Down
Original file line number Diff line number Diff line change
Expand Up @@ -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);
}
}
Original file line number Diff line number Diff line change
Expand Up @@ -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"
Expand Down
2 changes: 2 additions & 0 deletions src/test/shell/integration/starlark_configurations_test.sh
Original file line number Diff line number Diff line change
Expand Up @@ -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"
Expand Down

2 comments on commit 6e945e8

@SalmaSamy
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Hi @justinhorvitz it looks like this broke bazel watcher (found by Culprit). Can you please check it?

@justinhorvitz
Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I am not familiar with that failing test, however this change is an intentional behavior change with print statements, so it is likely that the test's expectations need to be updated. The changes are documented in the description.

Please sign in to comment.