Properly report repo fetch progress during main repo mapping computation

This ends up as simple as firing an event and letting UiEventHandler know that the build has started. Fixes #16927. Fixes #16338. PiperOrigin-RevId: 511177491 Change-Id: I479b116cf896731b7238410ce14f7e249da6c390
bazelbuild · Feb 21, 2023 · 31b4f0c · 31b4f0c
1 parent 3ab8a0a
commit 31b4f0c
Show file tree

Hide file tree

Showing 8 changed files with 127 additions and 40 deletions.
diff --git a/...ogle/devtools/build/lib/buildtool/buildevent/MainRepoMappingComputationStartingEvent.java b/...ogle/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
@@ -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
@@ -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
@@ -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
@@ -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
@@ -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
@@ -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
@@ -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());
+  }
 }