Rate limit updates in the experimental UI and keep it fresh

Make the experimental UI honor the --show_progress_rate_limit flag.
While just dropping a status bar update if it happens too soon after
the last update shown would be easy, there are a few delecate points
to keep in mind.

Assume that several updates happen after another and then nothing for
a long time. Then the last(!) update is the one the user wants to see,
as it most accurately reflects which actions are running during the
long period. However, the simple dropping algorithms would show the
first of those state updates. So, whenever we refrain from updating due
to the rate limit we to make sure that an update will happen soon-ish,
even if no events are reported for a long time.

We do this by having (at most) one thread that periodically triggers
updates of the progress, if the rate limit allows this. This mechanism
is additionally used to ensure that the progress bar, when showing
time-dependent data is kept fresh. For this property we also add a test.

There is a third point to keep in mind: users (and also our tests) want
to see all phases. However, some phases (like loading) might be so short
that they happen in its entirety within a refresh interval. Therefore,
whenever a new important phase starts, we skip the rate limit interval
once; note that this happens at most a fixed number of times during the
entire build.

--
Change-Id: Iee68194d7eb92d6ef9efdc7abde6f56edfa21ce8
Reviewed-on: https://bazel-review.googlesource.com/#/c/3293
MOS_MIGRATED_REVID=119515272

2 files changed, 102 insertions, 8 deletions

diff --git a/src/main/java/com/google/devtools/build/lib/runtime/ExperimentalEventHandler.java b/src/main/java/com/google/devtools/build/lib/runtime/ExperimentalEventHandler.java
index e4b0128e3a..b852de611a 100644
--- a/src/main/java/com/google/devtools/build/lib/runtime/ExperimentalEventHandler.java
+++ b/src/main/java/com/google/devtools/build/lib/runtime/ExperimentalEventHandler.java
@@ -43,13 +43,18 @@ import java.util.logging.Logger;
 public class ExperimentalEventHandler extends BlazeCommandEventHandler {
   private static Logger LOG = Logger.getLogger(ExperimentalEventHandler.class.getName());
 
+  private final long minimalDelayMillis;
   private final boolean cursorControl;
+  private final Clock clock;
   private final AnsiTerminal terminal;
   private final boolean debugAllEvents;
   private final ExperimentalStateTracker stateTracker;
+  private final long minimalUpdateInterval;
+  private long lastRefreshMillis;
   private int numLinesProgressBar;
   private boolean buildComplete;
   private boolean progressBarNeedsRefresh;
+  private Thread updateThread;
 
   public final int terminalWidth;
 
@@ -59,9 +64,14 @@ public class ExperimentalEventHandler extends BlazeCommandEventHandler {
     this.cursorControl = options.useCursorControl();
     this.terminal = new AnsiTerminal(outErr.getErrorStream());
     this.terminalWidth = (options.terminalColumns > 0 ? options.terminalColumns : 80);
+    this.clock = clock;
     this.debugAllEvents = options.experimentalUiDebugAllEvents;
     this.stateTracker = new ExperimentalStateTracker(clock);
     this.numLinesProgressBar = 0;
+    this.minimalDelayMillis = Math.round(options.showProgressRateLimit * 1000);
+    this.minimalUpdateInterval = Math.max(this.minimalDelayMillis, 1000L);
+    // The progress bar has not been updated yet.
+    ignoreRefreshLimitOnce();
   }
 
   @Override
@@ -150,13 +160,18 @@ public class ExperimentalEventHandler extends BlazeCommandEventHandler {
   @Subscribe
   public void buildStarted(BuildStartingEvent event) {
     stateTracker.buildStarted(event);
+    // As a new phase started, inform immediately.
+    ignoreRefreshLimitOnce();
     refresh();
   }
 
   @Subscribe
   public void loadingStarted(LoadingPhaseStartedEvent event) {
     stateTracker.loadingStarted(event);
+    // As a new phase started, inform immediately.
+    ignoreRefreshLimitOnce();
     refresh();
+    startUpdateThread();
   }
 
   @Subscribe
@@ -174,6 +189,9 @@ public class ExperimentalEventHandler extends BlazeCommandEventHandler {
   @Subscribe
   public void progressReceiverAvailable(ExecutionProgressReceiverAvailableEvent event) {
     stateTracker.progressReceiverAvailable(event);
+    // As this is the first time we have a progress message, update immediately.
+    ignoreRefreshLimitOnce();
+    startUpdateThread();
   }
 
   @Subscribe
@@ -181,11 +199,13 @@ public class ExperimentalEventHandler extends BlazeCommandEventHandler {
     stateTracker.buildComplete(event);
     refresh();
     buildComplete = true;
+    stopUpdateThread();
   }
 
   @Subscribe
   public void noBuild(NoBuildEvent event) {
     buildComplete = true;
+    stopUpdateThread();
   }
 
   @Subscribe
@@ -206,15 +226,67 @@ public class ExperimentalEventHandler extends BlazeCommandEventHandler {
   }
 
   private synchronized void doRefresh() {
-    try {
-      if (progressBarNeedsRefresh) {
-        progressBarNeedsRefresh = false;
-        clearProgressBar();
-        addProgressBar();
-        terminal.flush();
+    long nowMillis = clock.currentTimeMillis();
+    if (lastRefreshMillis + minimalDelayMillis < nowMillis) {
+      try {
+        if (progressBarNeedsRefresh || stateTracker.progressBarTimeDependent()) {
+          progressBarNeedsRefresh = false;
+          lastRefreshMillis = nowMillis;
+          clearProgressBar();
+          addProgressBar();
+          terminal.flush();
+        }
+      } catch (IOException e) {
+        LOG.warning("IO Error writing to output stream: " + e);
       }
-    } catch (IOException e) {
-      LOG.warning("IO Error writing to output stream: " + e);
+      if (!stateTracker.progressBarTimeDependent()) {
+        stopUpdateThread();
+      }
+    } else {
+      // We skipped an update due to rate limiting. If this however, turned
+      // out to be the last update for a long while, we need to show it in a
+      // timely manner, as it best describes the current state.
+      startUpdateThread();
+    }
+  }
+
+  private void ignoreRefreshLimitOnce() {
+    // Set refresh time variables in a state such that the next progress bar
+    // update will definitely be written out.
+    lastRefreshMillis = clock.currentTimeMillis() - minimalDelayMillis - 1;
+  }
+
+  private synchronized void startUpdateThread() {
+    if (updateThread == null) {
+      final ExperimentalEventHandler eventHandler = this;
+      updateThread =
+          new Thread(
+              new Runnable() {
+                @Override
+                public void run() {
+                  try {
+                    while (true) {
+                      Thread.sleep(minimalUpdateInterval);
+                      eventHandler.doRefresh();
+                    }
+                  } catch (InterruptedException e) {
+                    // Ignore
+                  }
+                }
+              });
+      updateThread.start();
+    }
+  }
+
+  private synchronized void stopUpdateThread() {
+    if (updateThread != null) {
+      updateThread.interrupt();
+      try {
+        updateThread.join();
+      } catch (InterruptedException e) {
+        // Ignore
+      }
+      updateThread = null;
     }
   }
 
diff --git a/src/test/shell/integration/experimental_ui_test.sh b/src/test/shell/integration/experimental_ui_test.sh
index e411b53904..bb1f2c3f9c 100755
--- a/src/test/shell/integration/experimental_ui_test.sh
+++ b/src/test/shell/integration/experimental_ui_test.sh
@@ -35,6 +35,12 @@ function set_up() {
 exit 0
 EOF
   chmod 755 pkg/true.sh
+  cat > pkg/slow.sh <<EOF
+#!/bin/sh
+sleep 10
+exit 0
+EOF
+  chmod 755 pkg/slow.sh
   cat > pkg/false.sh <<EOF
 #!/bin/sh
 exit 1
@@ -46,6 +52,10 @@ sh_test(
   srcs = ["true.sh"],
 )
 sh_test(
+  name = "slow",
+  srcs = ["slow.sh"],
+)
+sh_test(
   name = "false",
   srcs = ["false.sh"],
 )
@@ -169,4 +179,16 @@ function test_loading_progress {
   expect_log 'Loading.*[0-9,]* / [0-9,]*'
 }
 
+function test_times_fresh {
+  bazel clean || fail "bazel clean failed"
+  bazel test --experimental_ui --curses=yes --color=yes pkg:slow 2>$TEST_log \
+    || fail "bazel test failed"
+  # We have ensured that the slow test is run. It takes at least 10 seconds
+  # and we expect an update about once per second. Due to lack of knowledge
+  # of the phasing, we cannot expect a particular run-time to be visible;
+  # however, if none of three adjacent seconds are shown in the upddate the
+  # refreshing is certainly not working.
+  expect_log 'Testing.*slow.*[789]s'
+}
+
 run_suite "Integration tests for bazel's experimental UI"