From a2f013ac144db845e13830cd82c4acfe2455ae16 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?X=C3=B9d=C5=8Dng=20Y=C3=A1ng?= Date: Tue, 21 Feb 2023 16:07:51 +0100 Subject: [PATCH] Properly report repo fetch progress during main repo mapping computation (#17544) This ends up as simple as firing an event and letting UiEventHandler know that the build has started. Fixes https://github.com/bazelbuild/bazel/issues/16927. Fixes https://github.com/bazelbuild/bazel/issues/16338. PiperOrigin-RevId: 511177491 Change-Id: I479b116cf896731b7238410ce14f7e249da6c390 --- ...inRepoMappingComputationStartingEvent.java | 21 +++++ .../lib/runtime/BlazeCommandDispatcher.java | 2 + .../lib/runtime/SkymeldUiStateTracker.java | 9 ++ .../build/lib/runtime/UiEventHandler.java | 13 ++- .../build/lib/runtime/UiStateTracker.java | 5 ++ .../UiEventHandlerStdOutAndStdErrTest.java | 20 +++-- .../build/lib/runtime/UiStateTrackerTest.java | 90 ++++++++++++------- .../build/lib/testutil/ManualClock.java | 7 ++ 8 files changed, 127 insertions(+), 40 deletions(-) create mode 100644 src/main/java/com/google/devtools/build/lib/buildtool/buildevent/MainRepoMappingComputationStartingEvent.java diff --git a/src/main/java/com/google/devtools/build/lib/buildtool/buildevent/MainRepoMappingComputationStartingEvent.java b/src/main/java/com/google/devtools/build/lib/buildtool/buildevent/MainRepoMappingComputationStartingEvent.java new file mode 100644 index 00000000000000..7a888279b863b7 --- /dev/null +++ b/src/main/java/com/google/devtools/build/lib/buildtool/buildevent/MainRepoMappingComputationStartingEvent.java @@ -0,0 +1,21 @@ +// Copyright 2023 The Bazel Authors. All rights reserved. +// +// Licensed under the Apache License, Version 2.0 (the "License"); +// you may not use this file except in compliance with the License. +// You may obtain a copy of the License at +// +// http://www.apache.org/licenses/LICENSE-2.0 +// +// Unless required by applicable law or agreed to in writing, software +// distributed under the License is distributed on an "AS IS" BASIS, +// WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. +// See the License for the specific language governing permissions and +// limitations under the License. + +package com.google.devtools.build.lib.buildtool.buildevent; + +/** + * Event fired right before main repo mapping computation starts (between the two rounds of option + * parsing). + */ +public class MainRepoMappingComputationStartingEvent {} diff --git a/src/main/java/com/google/devtools/build/lib/runtime/BlazeCommandDispatcher.java b/src/main/java/com/google/devtools/build/lib/runtime/BlazeCommandDispatcher.java index 076a7b365e4e95..0fbd5a2d3f0327 100644 --- a/src/main/java/com/google/devtools/build/lib/runtime/BlazeCommandDispatcher.java +++ b/src/main/java/com/google/devtools/build/lib/runtime/BlazeCommandDispatcher.java @@ -32,6 +32,7 @@ import com.google.devtools.build.lib.bugreport.Crash; import com.google.devtools.build.lib.bugreport.CrashContext; import com.google.devtools.build.lib.buildeventstream.BuildEventProtocolOptions; +import com.google.devtools.build.lib.buildtool.buildevent.MainRepoMappingComputationStartingEvent; import com.google.devtools.build.lib.buildtool.buildevent.ProfilerStartedEvent; import com.google.devtools.build.lib.clock.BlazeClock; import com.google.devtools.build.lib.cmdline.RepositoryMapping; @@ -547,6 +548,7 @@ private BlazeCommandResult execExclusively( // Compute the repo mapping of the main repo and re-parse options so that we get correct // values for label-typed options. + env.getEventBus().post(new MainRepoMappingComputationStartingEvent()); try { RepositoryMapping mainRepoMapping = env.getSkyframeExecutor().getMainRepoMapping(reporter); diff --git a/src/main/java/com/google/devtools/build/lib/runtime/SkymeldUiStateTracker.java b/src/main/java/com/google/devtools/build/lib/runtime/SkymeldUiStateTracker.java index 6ce72a6cd894cc..078316c9a103b8 100644 --- a/src/main/java/com/google/devtools/build/lib/runtime/SkymeldUiStateTracker.java +++ b/src/main/java/com/google/devtools/build/lib/runtime/SkymeldUiStateTracker.java @@ -35,6 +35,7 @@ enum BuildStatus { // We explicitly define a starting status, which can be used to determine what to display in // cases before the build has started. BUILD_NOT_STARTED, + COMPUTING_MAIN_REPO_MAPPING, BUILD_STARTED, TARGET_PATTERN_PARSING, LOADING_COMPLETE, @@ -77,6 +78,9 @@ synchronized void writeProgressBar( switch (buildStatus) { case BUILD_NOT_STARTED: return; + case COMPUTING_MAIN_REPO_MAPPING: + writeBaseProgress("Computing main repo mapping", "", terminalWriter); + break; case BUILD_STARTED: writeBaseProgress("Loading", "", terminalWriter); break; @@ -151,6 +155,11 @@ void writeLoadingAnalysisPhaseProgress( } } + @Override + void mainRepoMappingComputationStarted() { + buildStatus = BuildStatus.COMPUTING_MAIN_REPO_MAPPING; + } + @Override void buildStarted() { buildStatus = BuildStatus.BUILD_STARTED; diff --git a/src/main/java/com/google/devtools/build/lib/runtime/UiEventHandler.java b/src/main/java/com/google/devtools/build/lib/runtime/UiEventHandler.java index eb59e4fe4e0c42..bea9c3854ae3a3 100644 --- a/src/main/java/com/google/devtools/build/lib/runtime/UiEventHandler.java +++ b/src/main/java/com/google/devtools/build/lib/runtime/UiEventHandler.java @@ -40,6 +40,7 @@ import com.google.devtools.build.lib.buildtool.buildevent.BuildCompleteEvent; import com.google.devtools.build.lib.buildtool.buildevent.BuildStartingEvent; import com.google.devtools.build.lib.buildtool.buildevent.ExecutionProgressReceiverAvailableEvent; +import com.google.devtools.build.lib.buildtool.buildevent.MainRepoMappingComputationStartingEvent; import com.google.devtools.build.lib.buildtool.buildevent.TestFilteringCompleteEvent; import com.google.devtools.build.lib.clock.Clock; import com.google.devtools.build.lib.events.Event; @@ -517,7 +518,7 @@ private void setEventKindColor(EventKind kind) throws IOException { } @Subscribe - public void buildStarted(BuildStartingEvent event) { + public void mainRepoMappingComputationStarted(MainRepoMappingComputationStartingEvent event) { synchronized (this) { buildRunning = true; } @@ -526,6 +527,16 @@ public void buildStarted(BuildStartingEvent event) { // As a new phase started, inform immediately. ignoreRefreshLimitOnce(); refresh(); + startUpdateThread(); + } + + @Subscribe + public void buildStarted(BuildStartingEvent event) { + maybeAddDate(); + stateTracker.buildStarted(); + // As a new phase started, inform immediately. + ignoreRefreshLimitOnce(); + refresh(); } @Subscribe diff --git a/src/main/java/com/google/devtools/build/lib/runtime/UiStateTracker.java b/src/main/java/com/google/devtools/build/lib/runtime/UiStateTracker.java index 14183b40c01d6b..116e25bb8e6a41 100644 --- a/src/main/java/com/google/devtools/build/lib/runtime/UiStateTracker.java +++ b/src/main/java/com/google/devtools/build/lib/runtime/UiStateTracker.java @@ -409,6 +409,11 @@ void setProgressSampleSize(int sampleSize) { this.sampleSize = Math.max(1, sampleSize); } + void mainRepoMappingComputationStarted() { + status = "Computing main repo mapping"; + additionalMessage = ""; + } + void buildStarted() { status = "Loading"; additionalMessage = ""; diff --git a/src/test/java/com/google/devtools/build/lib/runtime/UiEventHandlerStdOutAndStdErrTest.java b/src/test/java/com/google/devtools/build/lib/runtime/UiEventHandlerStdOutAndStdErrTest.java index da52662a897c69..8d41a6324e26d8 100644 --- a/src/test/java/com/google/devtools/build/lib/runtime/UiEventHandlerStdOutAndStdErrTest.java +++ b/src/test/java/com/google/devtools/build/lib/runtime/UiEventHandlerStdOutAndStdErrTest.java @@ -23,6 +23,7 @@ import com.google.devtools.build.lib.buildtool.BuildResult; import com.google.devtools.build.lib.buildtool.buildevent.BuildCompleteEvent; import com.google.devtools.build.lib.buildtool.buildevent.BuildStartingEvent; +import com.google.devtools.build.lib.buildtool.buildevent.MainRepoMappingComputationStartingEvent; import com.google.devtools.build.lib.events.Event; import com.google.devtools.build.lib.events.EventKind; import com.google.devtools.build.lib.testutil.ManualClock; @@ -70,23 +71,24 @@ private void createUiEventHandler(UiOptions uiOptions) { OutErr outErr = null; switch (testedOutput) { case STDOUT: - outErr = OutErr.create(/*out=*/ output, /*err=*/ mock(OutputStream.class)); + outErr = OutErr.create(/* out= */ output, /* err= */ mock(OutputStream.class)); eventKind = EventKind.STDOUT; break; case STDERR: - outErr = OutErr.create(/*out=*/ mock(OutputStream.class), /*err=*/ output); + outErr = OutErr.create(/* out= */ mock(OutputStream.class), /* err= */ output); eventKind = EventKind.STDERR; break; } uiEventHandler = - new UiEventHandler(outErr, uiOptions, new ManualClock(), /*workspacePathFragment=*/ null); + new UiEventHandler(outErr, uiOptions, new ManualClock(), /* workspacePathFragment= */ null); + uiEventHandler.mainRepoMappingComputationStarted(new MainRepoMappingComputationStartingEvent()); uiEventHandler.buildStarted( BuildStartingEvent.create( "outputFileSystemType", - /*usesInMemoryFileSystem=*/ false, + /* usesInMemoryFileSystem= */ false, mock(BuildRequest.class), - /*workspace=*/ null, + /* workspace= */ null, "/pwd")); } @@ -169,7 +171,7 @@ public void noChangeOnUnflushedWrite() { uiOptions.eventFilters = ImmutableList.of(); createUiEventHandler(uiOptions); if (testedOutput == TestedOutput.STDERR) { - assertThat(output.flushed).hasSize(1); + assertThat(output.flushed).hasSize(2); output.flushed.clear(); } // Unterminated strings are saved in memory and not pushed out at all. @@ -190,9 +192,9 @@ public void buildCompleteMessageDoesntOverrideError() { uiEventHandler.handle(Event.error("Show me this!")); uiEventHandler.afterCommand(new AfterCommandEvent()); - assertThat(output.flushed.size()).isEqualTo(4); - assertThat(output.flushed.get(2)).contains("Show me this!"); - assertThat(output.flushed.get(3)).doesNotContain("\033[1A\033[K"); + assertThat(output.flushed.size()).isEqualTo(5); + assertThat(output.flushed.get(3)).contains("Show me this!"); + assertThat(output.flushed.get(4)).doesNotContain("\033[1A\033[K"); } private Event output(String message) { diff --git a/src/test/java/com/google/devtools/build/lib/runtime/UiStateTrackerTest.java b/src/test/java/com/google/devtools/build/lib/runtime/UiStateTrackerTest.java index fdd89a87513adf..13475497d5b95d 100644 --- a/src/test/java/com/google/devtools/build/lib/runtime/UiStateTrackerTest.java +++ b/src/test/java/com/google/devtools/build/lib/runtime/UiStateTrackerTest.java @@ -1289,59 +1289,89 @@ public void testSuffix() { } @Test - public void testDownloadShown() throws Exception { - // Verify that, whenever a single download is running in loading face, it is shown in the status - // bar. + public void testDownloadShown_duringLoading() throws Exception { + // Verify that, whenever a single download is running in loading phase, it is shown in the + // status bar. ManualClock clock = new ManualClock(); - clock.advanceMillis(TimeUnit.SECONDS.toMillis(1234)); - UiStateTracker stateTracker = getUiStateTracker(clock, /*targetWidth=*/ 80); + clock.advance(Duration.ofSeconds(1234)); + UiStateTracker stateTracker = getUiStateTracker(clock, /* targetWidth= */ 80); URL url = new URL("http://example.org/first/dep"); stateTracker.buildStarted(); stateTracker.downloadProgress(new DownloadProgressEvent(url)); - clock.advanceMillis(TimeUnit.SECONDS.toMillis(6)); + clock.advance(Duration.ofSeconds(6)); - LoggingTerminalWriter terminalWriter = new LoggingTerminalWriter(/*discardHighlight=*/ true); + LoggingTerminalWriter terminalWriter = new LoggingTerminalWriter(/* discardHighlight= */ true); stateTracker.writeProgressBar(terminalWriter); String output = terminalWriter.getTranscript(); - assertWithMessage("Progress bar should contain '" + url.toString() + "', but was:\n" + output) - .that(output.contains(url.toString())) - .isTrue(); - assertWithMessage("Progress bar should contain '6s', but was:\n" + output) - .that(output.contains("6s")) - .isTrue(); + assertThat(output).contains(url.toString()); + assertThat(output).contains("6s"); // Progress on the pending download should be reported appropriately - clock.advanceMillis(TimeUnit.SECONDS.toMillis(1)); + clock.advance(Duration.ofSeconds(1)); stateTracker.downloadProgress(new DownloadProgressEvent(url, 256)); - terminalWriter = new LoggingTerminalWriter(/*discardHighlight=*/ true); + terminalWriter = new LoggingTerminalWriter(/* discardHighlight= */ true); stateTracker.writeProgressBar(terminalWriter); output = terminalWriter.getTranscript(); - assertWithMessage("Progress bar should contain '" + url.toString() + "', but was:\n" + output) - .that(output.contains(url.toString())) - .isTrue(); - assertWithMessage("Progress bar should contain '7s', but was:\n" + output) - .that(output.contains("7s")) - .isTrue(); - assertWithMessage("Progress bar should contain '256', but was:\n" + output) - .that(output.contains("256")) - .isTrue(); + assertThat(output).contains(url.toString()); + assertThat(output).contains("7s"); + assertThat(output).contains("256"); // After finishing the download, it should no longer be reported. - clock.advanceMillis(TimeUnit.SECONDS.toMillis(1)); + clock.advance(Duration.ofSeconds(1)); stateTracker.downloadProgress(new DownloadProgressEvent(url, 256, true)); - terminalWriter = new LoggingTerminalWriter(/*discardHighlight=*/ true); + terminalWriter = new LoggingTerminalWriter(/* discardHighlight= */ true); stateTracker.writeProgressBar(terminalWriter); output = terminalWriter.getTranscript(); - assertWithMessage("Progress bar should not contain url, but was:\n" + output) - .that(output.contains("example.org")) - .isFalse(); + assertThat(output).doesNotContain("example.org"); + } + + @Test + public void testDownloadShown_duringMainRepoMappingComputation() throws Exception { + ManualClock clock = new ManualClock(); + clock.advance(Duration.ofSeconds(1234)); + UiStateTracker stateTracker = getUiStateTracker(clock, /* targetWidth= */ 80); + + URL url = new URL("http://example.org/first/dep"); + + stateTracker.mainRepoMappingComputationStarted(); + stateTracker.downloadProgress(new DownloadProgressEvent(url)); + clock.advance(Duration.ofSeconds(6)); + + LoggingTerminalWriter terminalWriter = new LoggingTerminalWriter(/* discardHighlight= */ true); + stateTracker.writeProgressBar(terminalWriter); + String output = terminalWriter.getTranscript(); + + assertThat(output).contains(url.toString()); + assertThat(output).contains("6s"); + + // Progress on the pending download should be reported appropriately + clock.advance(Duration.ofSeconds(1)); + stateTracker.downloadProgress(new DownloadProgressEvent(url, 256)); + + terminalWriter = new LoggingTerminalWriter(/* discardHighlight= */ true); + stateTracker.writeProgressBar(terminalWriter); + output = terminalWriter.getTranscript(); + + assertThat(output).contains(url.toString()); + assertThat(output).contains("7s"); + assertThat(output).contains("256"); + + // After finishing the download, it should no longer be reported. + clock.advance(Duration.ofSeconds(1)); + stateTracker.downloadProgress(new DownloadProgressEvent(url, 256, true)); + + terminalWriter = new LoggingTerminalWriter(/* discardHighlight= */ true); + stateTracker.writeProgressBar(terminalWriter); + output = terminalWriter.getTranscript(); + + assertThat(output).doesNotContain("example.org"); } @Test @@ -1350,7 +1380,7 @@ public void testDownloadOutputLength() throws Exception { // Also verify that the length is respected, even if only a download sample is shown. ManualClock clock = new ManualClock(); clock.advanceMillis(TimeUnit.SECONDS.toMillis(1234)); - UiStateTracker stateTracker = getUiStateTracker(clock, /*targetWidth=*/ 60); + UiStateTracker stateTracker = getUiStateTracker(clock, /* targetWidth= */ 60); URL url = new URL("http://example.org/some/really/very/very/long/path/filename.tar.gz"); stateTracker.buildStarted(); diff --git a/src/test/java/com/google/devtools/build/lib/testutil/ManualClock.java b/src/test/java/com/google/devtools/build/lib/testutil/ManualClock.java index 3bc1d4137f2028..3316ce15b14a0d 100644 --- a/src/test/java/com/google/devtools/build/lib/testutil/ManualClock.java +++ b/src/test/java/com/google/devtools/build/lib/testutil/ManualClock.java @@ -15,6 +15,8 @@ package com.google.devtools.build.lib.testutil; import com.google.devtools.build.lib.clock.Clock; +import com.google.errorprone.annotations.CanIgnoreReturnValue; +import java.time.Duration; import java.util.concurrent.TimeUnit; import java.util.concurrent.atomic.AtomicLong; @@ -43,4 +45,9 @@ public long nanoTime() { public long advanceMillis(long time) { return currentTimeMillis.addAndGet(time); } + + @CanIgnoreReturnValue + public long advance(Duration duration) { + return advanceMillis(duration.toMillis()); + } }