experimental UI: track touched packages during loading/analysis

To give a better understanding of which packages are on the critical
path during loading and analysis, provide information in the same way
as during execution: show the earliest started, but not yet completed
package. As not all packages looked at during the analysis phase are
reported to the progress receiver, use a custom class to aggregate those
data.

--
Change-Id: I03c25efdecb4124e1bc06fce8be9175dc56b5500
Reviewed-on: https://bazel-review.googlesource.com/#/c/3700
MOS_MIGRATED_REVID=123408689

8 files changed, 244 insertions, 42 deletions

diff --git a/src/main/java/com/google/devtools/build/lib/runtime/ExperimentalStateTracker.java b/src/main/java/com/google/devtools/build/lib/runtime/ExperimentalStateTracker.java
index 769260a2e6..44e38f08b4 100644
--- a/src/main/java/com/google/devtools/build/lib/runtime/ExperimentalStateTracker.java
+++ b/src/main/java/com/google/devtools/build/lib/runtime/ExperimentalStateTracker.java
@@ -26,8 +26,9 @@ import com.google.devtools.build.lib.buildtool.buildevent.TestFilteringCompleteE
 import com.google.devtools.build.lib.cmdline.Label;
 import com.google.devtools.build.lib.pkgcache.LoadingPhaseCompleteEvent;
 import com.google.devtools.build.lib.skyframe.LoadingPhaseStartedEvent;
-import com.google.devtools.build.lib.skyframe.LoadingProgressReceiver;
+import com.google.devtools.build.lib.skyframe.PackageProgressReceiver;
 import com.google.devtools.build.lib.util.Clock;
+import com.google.devtools.build.lib.util.Pair;
 import com.google.devtools.build.lib.util.io.AnsiTerminalWriter;
 import com.google.devtools.build.lib.util.io.PositionAwareAnsiTerminalWriter;
 import com.google.devtools.build.lib.view.test.TestStatus.BlazeTestStatus;
@@ -40,7 +41,6 @@ import java.util.Map;
 import java.util.Set;
 import java.util.TreeMap;
 import java.util.TreeSet;
-import java.util.concurrent.atomic.AtomicInteger;
 
 /**
  * An experimental state tracker for the new experimental UI.
@@ -83,8 +83,7 @@ class ExperimentalStateTracker {
   private boolean ok;
 
   private ExecutionProgressReceiver executionProgressReceiver;
-  private LoadingProgressReceiver loadingProgressReceiver;
-  private AtomicInteger numPackagesLoaded;
+  private PackageProgressReceiver packageProgressReceiver;
 
   ExperimentalStateTracker(Clock clock, int targetWidth) {
     this.runningActions = new ArrayDeque<>();
@@ -107,12 +106,10 @@ class ExperimentalStateTracker {
 
   void loadingStarted(LoadingPhaseStartedEvent event) {
     status = null;
-    loadingProgressReceiver = event.getLoadingProgressReceiver();
-    numPackagesLoaded = event.getNumPackagesLoaded();
+    packageProgressReceiver = event.getPackageProgressReceiver();
   }
 
   void loadingComplete(LoadingPhaseCompleteEvent event) {
-    loadingProgressReceiver = null;
     int count = event.getTargets().size();
     status = "Analyzing";
     if (count == 1) {
@@ -124,7 +121,7 @@ class ExperimentalStateTracker {
 
   void analysisComplete(AnalysisPhaseCompleteEvent event) {
     status = null;
-    numPackagesLoaded = null;
+    packageProgressReceiver = null;
   }
 
   void progressReceiverAvailable(ExecutionProgressReceiverAvailableEvent event) {
@@ -388,7 +385,7 @@ class ExperimentalStateTracker {
    * bar shows time information relative to the current time.
    */
   boolean progressBarTimeDependent() {
-    if (numPackagesLoaded != null) {
+    if (packageProgressReceiver != null) {
       return true;
     }
     if (status != null) {
@@ -397,12 +394,6 @@ class ExperimentalStateTracker {
     if (runningActions.size() >= 1) {
       return true;
     }
-    if (loadingProgressReceiver != null) {
-      // This is kind-of a hack: since the event handler does not get informed about updates
-      // in the loading phase, indicate that the progress bar might change even though no
-      // explicit update event is known to the event handler.
-      return true;
-    }
     return false;
   }
 
@@ -441,17 +432,21 @@ class ExperimentalStateTracker {
         terminalWriter.failStatus();
       }
       terminalWriter.append(status + ":").normal().append(" " + additionalMessage);
-      if (numPackagesLoaded != null) {
-        terminalWriter.append(" (" + numPackagesLoaded.get() + " packages loaded)");
+      if (packageProgressReceiver != null) {
+        Pair<String, String> progress = packageProgressReceiver.progressState();
+        terminalWriter.append(" (" + progress.getFirst() + ")");
+        if (progress.getSecond().length() > 0) {
+          terminalWriter.newline().append("    " + progress.getSecond());
+        }
       }
       return;
     }
-    if (loadingProgressReceiver != null) {
-      terminalWriter
-          .okStatus()
-          .append("Loading:")
-          .normal()
-          .append(" " + loadingProgressReceiver.progressState());
+    if (packageProgressReceiver != null) {
+      Pair<String, String> progress = packageProgressReceiver.progressState();
+      terminalWriter.okStatus().append("Loading:").normal().append(" " + progress.getFirst());
+      if (progress.getSecond().length() > 0) {
+        terminalWriter.newline().append("    " + progress.getSecond());
+      }
       return;
     }
     if (executionProgressReceiver != null) {
diff --git a/src/main/java/com/google/devtools/build/lib/skyframe/LoadingPhaseStartedEvent.java b/src/main/java/com/google/devtools/build/lib/skyframe/LoadingPhaseStartedEvent.java
index e3e7444688..88bb44bfa9 100644
--- a/src/main/java/com/google/devtools/build/lib/skyframe/LoadingPhaseStartedEvent.java
+++ b/src/main/java/com/google/devtools/build/lib/skyframe/LoadingPhaseStartedEvent.java
@@ -13,31 +13,23 @@
 // limitations under the License.
 package com.google.devtools.build.lib.skyframe;
 
-import java.util.concurrent.atomic.AtomicInteger;
 /**
  * This event is fired at the beginning of the loading phase.
  */
 public final class LoadingPhaseStartedEvent {
 
-  final LoadingProgressReceiver loadingProgressReceiver;
-  final AtomicInteger numPackagesLoaded;
+  final PackageProgressReceiver packageProgress;
 
   /**
    * Construct the event
    *
    * @param loadingProgressReceiver a receiver that gets updated about the progress of loading
    */
-  public LoadingPhaseStartedEvent(
-      LoadingProgressReceiver loadingProgressReceiver, AtomicInteger numPackagesLoaded) {
-    this.loadingProgressReceiver = loadingProgressReceiver;
-    this.numPackagesLoaded = numPackagesLoaded;
+  public LoadingPhaseStartedEvent(PackageProgressReceiver packageProgress) {
+    this.packageProgress = packageProgress;
   }
 
-  public LoadingProgressReceiver getLoadingProgressReceiver() {
-    return loadingProgressReceiver;
-  }
-
-  public AtomicInteger getNumPackagesLoaded() {
-    return numPackagesLoaded;
+  public PackageProgressReceiver getPackageProgressReceiver() {
+    return packageProgress;
   }
 }
diff --git a/src/main/java/com/google/devtools/build/lib/skyframe/PackageFunction.java b/src/main/java/com/google/devtools/build/lib/skyframe/PackageFunction.java
index 467b7a73f8..cb0d288788 100644
--- a/src/main/java/com/google/devtools/build/lib/skyframe/PackageFunction.java
+++ b/src/main/java/com/google/devtools/build/lib/skyframe/PackageFunction.java
@@ -91,6 +91,7 @@ public class PackageFunction implements SkyFunction {
   private final Cache<PackageIdentifier, CacheEntryWithGlobDeps<AstAfterPreprocessing>> astCache;
   private final AtomicBoolean showLoadingProgress;
   private final AtomicInteger numPackagesLoaded;
+  private final PackageProgressReceiver packageProgress;
   private final Profiler profiler = Profiler.instance();
   private final Label preludeLabel;
 
@@ -106,7 +107,8 @@ public class PackageFunction implements SkyFunction {
       Cache<PackageIdentifier, CacheEntryWithGlobDeps<Package.Builder>> packageFunctionCache,
       Cache<PackageIdentifier, CacheEntryWithGlobDeps<AstAfterPreprocessing>> astCache,
       AtomicInteger numPackagesLoaded,
-      @Nullable SkylarkImportLookupFunction skylarkImportLookupFunctionForInlining) {
+      @Nullable SkylarkImportLookupFunction skylarkImportLookupFunctionForInlining,
+      @Nullable PackageProgressReceiver packageProgress) {
     this.skylarkImportLookupFunctionForInlining = skylarkImportLookupFunctionForInlining;
     // Can be null in tests.
     this.preludeLabel = packageFactory == null
@@ -118,6 +120,26 @@ public class PackageFunction implements SkyFunction {
     this.packageFunctionCache = packageFunctionCache;
     this.astCache = astCache;
     this.numPackagesLoaded = numPackagesLoaded;
+    this.packageProgress = packageProgress;
+  }
+
+  public PackageFunction(
+      PackageFactory packageFactory,
+      CachingPackageLocator pkgLocator,
+      AtomicBoolean showLoadingProgress,
+      Cache<PackageIdentifier, CacheEntryWithGlobDeps<Package.Builder>> packageFunctionCache,
+      Cache<PackageIdentifier, CacheEntryWithGlobDeps<AstAfterPreprocessing>> astCache,
+      AtomicInteger numPackagesLoaded,
+      @Nullable SkylarkImportLookupFunction skylarkImportLookupFunctionForInlining) {
+    this(
+        packageFactory,
+        pkgLocator,
+        showLoadingProgress,
+        packageFunctionCache,
+        astCache,
+        numPackagesLoaded,
+        skylarkImportLookupFunctionForInlining,
+        null);
   }
 
   public void setSkylarkImportLookupFunctionForInliningForTesting(
@@ -1096,6 +1118,9 @@ public class PackageFunction implements SkyFunction {
         packageFunctionCache.getIfPresent(packageId);
     if (packageFunctionCacheEntry == null) {
       profiler.startTask(ProfilerTask.CREATE_PACKAGE, packageId.toString());
+      if (packageProgress != null) {
+        packageProgress.startReadPackage(packageId);
+      }
       try {
         CacheEntryWithGlobDeps<AstAfterPreprocessing> astCacheEntry =
             astCache.getIfPresent(packageId);
@@ -1183,6 +1208,9 @@ public class PackageFunction implements SkyFunction {
         packageFunctionCacheEntry =
             new CacheEntryWithGlobDeps<>(pkgBuilder, globDepsRequested, null);
         numPackagesLoaded.incrementAndGet();
+        if (packageProgress != null) {
+          packageProgress.doneReadPackage(packageId);
+        }
         packageFunctionCache.put(packageId, packageFunctionCacheEntry);
       } finally {
         profiler.completeTask(ProfilerTask.CREATE_PACKAGE);
diff --git a/src/main/java/com/google/devtools/build/lib/skyframe/PackageProgressReceiver.java b/src/main/java/com/google/devtools/build/lib/skyframe/PackageProgressReceiver.java
new file mode 100644
index 0000000000..4faf952dd9
--- /dev/null
+++ b/src/main/java/com/google/devtools/build/lib/skyframe/PackageProgressReceiver.java
@@ -0,0 +1,73 @@
+// Copyright 2016 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.skyframe;
+
+import com.google.devtools.build.lib.cmdline.PackageIdentifier;
+
+import com.google.devtools.build.lib.util.Pair;
+
+import java.util.ArrayDeque;
+import java.util.Deque;
+
+/**
+ * A class that, when beeing told about start and end of a package
+ * being loaded, keeps track of the loading progress and provides it
+ * as a human-readable string intened for the progress bar.
+ */
+public class PackageProgressReceiver {
+
+  private int packagesCompleted;
+  private Deque<PackageIdentifier> pending = new ArrayDeque<>();
+
+  /**
+   * Register that loading a package has started.
+   */
+  public synchronized void startReadPackage(PackageIdentifier packageId) {
+    pending.addLast(packageId);
+  }
+
+  /**
+   * Register that loding a package has completed.
+   */
+  public synchronized void doneReadPackage(PackageIdentifier packageId) {
+    packagesCompleted++;
+    pending.remove(packageId);
+  }
+
+  /**
+   * Reset all instance variables of this object to a state equal to that of a newly
+   * constructed object.
+   */
+  public synchronized void reset() {
+    packagesCompleted = 0;
+    pending = new ArrayDeque<>();
+  }
+
+  /**
+   * Return the ordered pair of a consistent snapshot of the state, consisting of a human-readable
+   * description of the progress achieved so far and a human readable description of the currently
+   * running activities. The later always include the oldest loading package not finished loading.
+   */
+  public synchronized Pair<String, String> progressState() {
+    String progress = "" + packagesCompleted + " packages loaded";
+    StringBuffer activity = new StringBuffer();
+    if (pending.size() > 0) {
+      activity.append("currently loading: ").append(pending.peekFirst().toString());
+      if (pending.size() > 1) {
+        activity.append(" ... (" + pending.size() + " packages)");
+      }
+    }
+    return new Pair<String, String>(progress, activity.toString());
+  }
+}
diff --git a/src/main/java/com/google/devtools/build/lib/skyframe/SkyframeExecutor.java b/src/main/java/com/google/devtools/build/lib/skyframe/SkyframeExecutor.java
index 201000d195..2246515a36 100644
--- a/src/main/java/com/google/devtools/build/lib/skyframe/SkyframeExecutor.java
+++ b/src/main/java/com/google/devtools/build/lib/skyframe/SkyframeExecutor.java
@@ -200,6 +200,7 @@ public abstract class SkyframeExecutor implements WalkableGraphFactory {
       newAstCache();
 
   private final AtomicInteger numPackagesLoaded = new AtomicInteger(0);
+  private final PackageProgressReceiver packageProgress = new PackageProgressReceiver();
 
   protected SkyframeBuildView skyframeBuildView;
   private ActionLogBufferPathGenerator actionLogBufferPathGenerator;
@@ -368,7 +369,8 @@ public abstract class SkyframeExecutor implements WalkableGraphFactory {
             packageFunctionCache,
             astCache,
             numPackagesLoaded,
-            ruleClassProvider));
+            ruleClassProvider,
+            packageProgress));
     map.put(SkyFunctions.PACKAGE_ERROR, new PackageErrorFunction());
     map.put(SkyFunctions.TARGET_MARKER, new TargetMarkerFunction());
     map.put(SkyFunctions.TRANSITIVE_TARGET, new TransitiveTargetFunction(ruleClassProvider));
@@ -420,7 +422,8 @@ public abstract class SkyframeExecutor implements WalkableGraphFactory {
       Cache<PackageIdentifier, CacheEntryWithGlobDeps<Builder>> packageFunctionCache,
       Cache<PackageIdentifier, CacheEntryWithGlobDeps<AstAfterPreprocessing>> astCache,
       AtomicInteger numPackagesLoaded,
-      RuleClassProvider ruleClassProvider) {
+      RuleClassProvider ruleClassProvider,
+      PackageProgressReceiver packageProgress) {
     return new PackageFunction(
         pkgFactory,
         packageManager,
@@ -428,7 +431,8 @@ public abstract class SkyframeExecutor implements WalkableGraphFactory {
         packageFunctionCache,
         astCache,
         numPackagesLoaded,
-        null);
+        null,
+        packageProgress);
   }
 
   protected SkyFunction newSkylarkImportLookupFunction(
@@ -936,6 +940,7 @@ public abstract class SkyframeExecutor implements WalkableGraphFactory {
     packageFunctionCache.invalidateAll();
     astCache.invalidateAll();
     numPackagesLoaded.set(0);
+    packageProgress.reset();
 
     // Reset the stateful SkyframeCycleReporter, which contains cycles from last run.
     cyclesReporter.set(createCyclesReporter());
@@ -1732,7 +1737,7 @@ public abstract class SkyframeExecutor implements WalkableGraphFactory {
           TestFilter.forOptions(options, eventHandler, ruleClassNames));
       EvaluationResult<TargetPatternPhaseValue> evalResult;
       LoadingProgressReceiver loadingProgressReceiver = new LoadingProgressReceiver();
-      eventBus.post(new LoadingPhaseStartedEvent(loadingProgressReceiver, numPackagesLoaded));
+      eventBus.post(new LoadingPhaseStartedEvent(packageProgress));
       progressReceiver.loadingProgressReceiver = loadingProgressReceiver;
       try {
         evalResult =
diff --git a/src/test/java/com/google/devtools/build/lib/runtime/ExperimentalStateTrackerTest.java b/src/test/java/com/google/devtools/build/lib/runtime/ExperimentalStateTrackerTest.java
index a276bc516b..ae6ec139cf 100644
--- a/src/test/java/com/google/devtools/build/lib/runtime/ExperimentalStateTrackerTest.java
+++ b/src/test/java/com/google/devtools/build/lib/runtime/ExperimentalStateTrackerTest.java
@@ -27,9 +27,12 @@ import com.google.devtools.build.lib.actions.Root;
 import com.google.devtools.build.lib.analysis.ConfiguredTarget;
 import com.google.devtools.build.lib.buildtool.buildevent.TestFilteringCompleteEvent;
 import com.google.devtools.build.lib.cmdline.Label;
+import com.google.devtools.build.lib.skyframe.LoadingPhaseStartedEvent;
+import com.google.devtools.build.lib.skyframe.PackageProgressReceiver;
 import com.google.devtools.build.lib.testutil.FoundationTestCase;
 import com.google.devtools.build.lib.testutil.LoggingTerminalWriter;
 import com.google.devtools.build.lib.testutil.ManualClock;
+import com.google.devtools.build.lib.util.Pair;
 import com.google.devtools.build.lib.vfs.Path;
 import com.google.devtools.build.lib.vfs.PathFragment;
 import com.google.devtools.build.lib.view.test.TestStatus.BlazeTestStatus;
@@ -67,6 +70,35 @@ public class ExperimentalStateTrackerTest extends FoundationTestCase {
   }
 
   @Test
+  public void testLoadingActivity() throws IOException {
+    // During loading phase, state and activity, as reported by the PackageProgressReceiver,
+    // should be visible in the progress bar.
+    String state = "42 packages loaded";
+    String activity = "currently loading //src/foo/bar and 17 more";
+    PackageProgressReceiver progress = Mockito.mock(PackageProgressReceiver.class);
+    when(progress.progressState()).thenReturn(new Pair<String, String>(state, activity));
+
+    ManualClock clock = new ManualClock();
+    ExperimentalStateTracker stateTracker = new ExperimentalStateTracker(clock);
+
+    stateTracker.loadingStarted(new LoadingPhaseStartedEvent(progress));
+
+    LoggingTerminalWriter terminalWriter = new LoggingTerminalWriter(/*discardHighlight=*/ true);
+    stateTracker.writeProgressBar(terminalWriter);
+    String output = terminalWriter.getTranscript();
+
+    assertTrue(
+        "Output should indicate that we are in the loading phase, but was:\n" + output,
+        output.contains("Loading"));
+    assertTrue(
+        "Output should contain loading state '" + state + "', but was:\n" + output,
+        output.contains(state));
+    assertTrue(
+        "Output should contain loading state '" + activity + "', but was:\n" + output,
+        output.contains(activity));
+  }
+
+  @Test
   public void testActionVisible() throws IOException {
     // If there is only one action running, it should be visible
     // somewhere in the progress bar, and also the short version thereof.
diff --git a/src/test/java/com/google/devtools/build/lib/skyframe/PackageProgressReceiverTest.java b/src/test/java/com/google/devtools/build/lib/skyframe/PackageProgressReceiverTest.java
new file mode 100644
index 0000000000..df35718a42
--- /dev/null
+++ b/src/test/java/com/google/devtools/build/lib/skyframe/PackageProgressReceiverTest.java
@@ -0,0 +1,77 @@
+// Copyright 2016 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.skyframe;
+
+import static org.junit.Assert.assertEquals;
+import static org.junit.Assert.assertFalse;
+import static org.junit.Assert.assertTrue;
+
+import com.google.devtools.build.lib.cmdline.PackageIdentifier;
+
+import org.junit.Test;
+import org.junit.runner.RunWith;
+import org.junit.runners.JUnit4;
+
+/**
+ * Tests {@link PackageProgressReceiver}.
+ */
+@RunWith(JUnit4.class)
+public class PackageProgressReceiverTest {
+
+  @Test
+  public void testPackageVisible() {
+    // If there is only a single package being loaded, it is visible in
+    // the activity part of the progress state.
+    PackageIdentifier id = PackageIdentifier.createInMainRepo("foo/bar/baz");
+    PackageProgressReceiver progress = new PackageProgressReceiver();
+    progress.startReadPackage(id);
+    String activity = progress.progressState().getSecond();
+
+    assertTrue(
+        "Unfinished package '" + id + "' should be visible in activity: " + activity,
+        activity.contains(id.toString()));
+  }
+
+  @Test
+  public void testPackageCounted() {
+    // If the loading of a package is completed, it is no longer visible as activity,
+    // but counted as one package fully loaded.
+    PackageIdentifier id = PackageIdentifier.createInMainRepo("foo/bar/baz");
+    PackageProgressReceiver progress = new PackageProgressReceiver();
+    progress.startReadPackage(id);
+    progress.doneReadPackage(id);
+    String state = progress.progressState().getFirst();
+    String activity = progress.progressState().getSecond();
+
+    assertFalse(
+        "Finished package '" + id + "' should not be visible in activity: " + activity,
+        activity.contains(id.toString()));
+    assertTrue(
+        "Number of completed packages should be visible in state", state.contains("1 package"));
+  }
+
+  @Test
+  public void testReset() {
+    // After resetting, messages should be as immediately after creation.
+    PackageProgressReceiver progress = new PackageProgressReceiver();
+    String defaultState = progress.progressState().getFirst();
+    String defaultActivity = progress.progressState().getSecond();
+    PackageIdentifier id = PackageIdentifier.createInMainRepo("foo/bar/baz");
+    progress.startReadPackage(id);
+    progress.doneReadPackage(id);
+    progress.reset();
+    assertEquals(defaultState, progress.progressState().getFirst());
+    assertEquals(defaultActivity, progress.progressState().getSecond());
+  }
+}
diff --git a/src/test/shell/integration/experimental_ui_test.sh b/src/test/shell/integration/experimental_ui_test.sh
index 490d0fe747..3734b7bb24 100755
--- a/src/test/shell/integration/experimental_ui_test.sh
+++ b/src/test/shell/integration/experimental_ui_test.sh
@@ -198,7 +198,7 @@ function test_loading_progress {
     --experimental_skyframe_target_pattern_evaluator pkg:true 2>$TEST_log \
     || fail "bazel test failed"
   # some progress indicator is shown during loading
-  expect_log 'Loading.*[0-9,]* / [0-9,]*'
+  expect_log 'Loading.*[0-9,]* packages'
 }
 
 function test_failure_scrollback_buffer_curses {