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"