Skip to content

Commit

Permalink
Properly report repo fetch progress during main repo mapping computat…
Browse files Browse the repository at this point in the history
…ion (bazelbuild#17544)

This ends up as simple as firing an event and letting UiEventHandler know that the build has started.

Fixes bazelbuild#16927.

Fixes bazelbuild#16338.

PiperOrigin-RevId: 511177491
Change-Id: I479b116cf896731b7238410ce14f7e249da6c390
  • Loading branch information
Wyverald authored Feb 21, 2023
1 parent 3ab8a0a commit a2f013a
Show file tree
Hide file tree
Showing 8 changed files with 127 additions and 40 deletions.
Original file line number Diff line number Diff line change
@@ -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 {}
Original file line number Diff line number Diff line change
Expand Up @@ -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;
Expand Down Expand Up @@ -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);
Expand Down
Original file line number Diff line number Diff line change
Expand Up @@ -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,
Expand Down Expand Up @@ -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;
Expand Down Expand Up @@ -151,6 +155,11 @@ void writeLoadingAnalysisPhaseProgress(
}
}

@Override
void mainRepoMappingComputationStarted() {
buildStatus = BuildStatus.COMPUTING_MAIN_REPO_MAPPING;
}

@Override
void buildStarted() {
buildStatus = BuildStatus.BUILD_STARTED;
Expand Down
Original file line number Diff line number Diff line change
Expand Up @@ -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;
Expand Down Expand Up @@ -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;
}
Expand All @@ -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
Expand Down
Original file line number Diff line number Diff line change
Expand Up @@ -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 = "";
Expand Down
Original file line number Diff line number Diff line change
Expand Up @@ -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;
Expand Down Expand Up @@ -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"));
}

Expand Down Expand Up @@ -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.
Expand 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) {
Expand Down
Original file line number Diff line number Diff line change
Expand Up @@ -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
Expand All @@ -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();
Expand Down
Original file line number Diff line number Diff line change
Expand Up @@ -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;

Expand Down Expand Up @@ -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());
}
}

0 comments on commit a2f013a

Please sign in to comment.