Remove logic that increases delay between progress updates over time

tom-cnops · copybara-github · commit a706994ac69e · 2022-10-27T03:11:12.000-07:00
Removes a bit of undocumented behavior that increases the delay between progress updates the longer the build is running. Potentially resolves bazelbuild#16119 Also renamed `MAXIMAL_UPDATE_DELAY_MILLIS` to `MINIMAL_UPDATE_INTERVAL_MILLIS` because it is used as a minimum and doesn't affect the delay between messages. Fixes bazelbuild#16119. Closes bazelbuild#16221. RELNOTES[INC]: Bazel no longer increases the delay between progress updates when there is no cursor control. PiperOrigin-RevId: 484203851 Change-Id: I33f7302ca85b75135744eb6093b618196199a49f
diff --git a/site/en/docs/user-manual.md b/site/en/docs/user-manual.md
@@ -790,6 +790,9 @@ The default is 0, that means an incremental algorithm: the first
 report will be printed after 10 seconds, then 30 seconds and after
 that progress is reported once every minute.
 
+When bazel is using cursor control, as specified by
+[`--curses`](#curses), progress is reported every second.
+
 #### `--local_{ram,cpu}_resources {{ "<var>" }}resources or resource expression{{ "</var>" }}` {:#local-resources}
 
 These options specify the amount of local resources (RAM in MB and number of CPU logical cores)
@@ -1129,11 +1132,10 @@ default. When disabled, progress messages are suppressed.
 
 #### `--show_progress_rate_limit={{ "<var>" }}n{{ "</var>" }}` {:#show-progress-rate}
 
-This option causes bazel to display only
-one progress message per `n` seconds, where {{ "<var>" }}n{{ "</var>" }} is a real number.
-If `n` is -1, all progress messages will be displayed. The default value for
-this option is 0.02, meaning bazel will limit the progress messages to one per every
-0.02 seconds.
+This option causes bazel to display at most one progress message per `n` seconds,
+where {{ "<var>" }}n{{ "</var>" }} is a real number.
+The default value for this option is 0.02, meaning bazel will limit the progress
+messages to one per every 0.02 seconds.
 
 #### `--show_result={{ "<var>" }}n{{ "</var>" }}` {:#show-result}
 
diff --git a/src/main/java/com/google/devtools/build/lib/buildtool/BuildRequestOptions.java b/src/main/java/com/google/devtools/build/lib/buildtool/BuildRequestOptions.java
@@ -73,8 +73,10 @@ public class BuildRequestOptions extends OptionsBase {
       effectTags = {OptionEffectTag.AFFECTS_OUTPUTS},
       converter = ProgressReportIntervalConverter.class,
       help =
-          "The number of seconds to wait between two reports on still running jobs. The "
-              + "default value 0 means to use the default 10:30:60 incremental algorithm.")
+          "The number of seconds to between reports on still running jobs. The "
+              + "default value 0 means the first report will be printed after 10 "
+              + "seconds, then 30 seconds and after that progress is reported once every minute. "
+              + "When --curses is enabled, progress is reported every second.")
   public int progressReportInterval;
 
   @Option(
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
@@ -81,27 +81,19 @@ public final class UiEventHandler implements EventHandler {
 
   private static final GoogleLogger logger = GoogleLogger.forEnclosingClass();
 
-  /** Latest refresh of the progress bar, if contents other than time changed */
-  private static final long MAXIMAL_UPDATE_DELAY_MILLIS = 200L;
+  /** Minimal time between scheduled updates */
+  private static final long MINIMAL_UPDATE_INTERVAL_MILLIS = 200L;
   /** Minimal rate limiting (in ms), if the progress bar cannot be updated in place */
   private static final long NO_CURSES_MINIMAL_PROGRESS_RATE_LIMIT = 1000L;
-  /**
-   * Minimal rate limiting, as fraction of the request time so far, if the progress bar cannot be
-   * updated in place
-   */
-  private static final double NO_CURSES_MINIMAL_RELATIVE_PROGRESS_RATE_LMIT = 0.15;
   /** Periodic update interval of a time-dependent progress bar if it can be updated in place */
   private static final long SHORT_REFRESH_MILLIS = 1000L;
-  /** Periodic update interval of a time-dependent progress bar if it cannot be updated in place */
-  private static final long LONG_REFRESH_MILLIS = 20000L;
 
   private static final DateTimeFormatter TIMESTAMP_FORMAT =
       DateTimeFormatter.ofPattern("(HH:mm:ss) ");
   private static final DateTimeFormatter DATE_FORMAT = DateTimeFormatter.ofPattern("yyyy-MM-dd");
 
   private final boolean cursorControl;
   private final Clock clock;
-  private final long uiStartTimeMillis;
   private final AnsiTerminal terminal;
   private final boolean debugAllEvents;
   private final UiStateTracker stateTracker;
@@ -111,7 +103,7 @@ public final class UiEventHandler implements EventHandler {
   private final boolean showTimestamp;
   private final OutErr outErr;
   private final ImmutableSet<EventKind> filteredEvents;
-  private long minimalDelayMillis;
+  private long progressRateLimitMillis;
   private long minimalUpdateInterval;
   private long lastRefreshMillis;
   private long mustRefreshAfterMillis;
@@ -175,7 +167,6 @@ public UiEventHandler(
     this.progressInTermTitle = options.progressInTermTitle && options.useCursorControl();
     this.showTimestamp = options.showTimestamp;
     this.clock = clock;
-    this.uiStartTimeMillis = clock.currentTimeMillis();
     this.debugAllEvents = options.experimentalUiDebugAllEvents;
     this.locationPrinter =
         new LocationPrinter(options.attemptToPrintRelativePaths, workspacePathFragment);
@@ -200,14 +191,15 @@ public UiEventHandler(
     this.stateTracker.setProgressSampleSize(options.uiActionsShown);
     this.numLinesProgressBar = 0;
     if (this.cursorControl) {
-      this.minimalDelayMillis = Math.round(options.showProgressRateLimit * 1000);
+      this.progressRateLimitMillis = Math.round(options.showProgressRateLimit * 1000);
     } else {
-      this.minimalDelayMillis =
+      this.progressRateLimitMillis =
           Math.max(
               Math.round(options.showProgressRateLimit * 1000),
               NO_CURSES_MINIMAL_PROGRESS_RATE_LIMIT);
     }
-    this.minimalUpdateInterval = Math.max(this.minimalDelayMillis, MAXIMAL_UPDATE_DELAY_MILLIS);
+    this.minimalUpdateInterval =
+        Math.max(this.progressRateLimitMillis, MINIMAL_UPDATE_INTERVAL_MILLIS);
     this.stdoutLineBuffer = new ByteArrayOutputStream();
     this.stderrLineBuffer = new ByteArrayOutputStream();
     this.dateShown = false;
@@ -854,7 +846,7 @@ private void doRefresh(boolean fromUpdateThread) {
       return;
     }
     long nowMillis = clock.currentTimeMillis();
-    if (lastRefreshMillis + minimalDelayMillis < nowMillis) {
+    if (lastRefreshMillis + progressRateLimitMillis < nowMillis) {
       if (updateLock.tryLock()) {
         try {
           synchronized (this) {
@@ -863,17 +855,6 @@ private void doRefresh(boolean fromUpdateThread) {
               clearProgressBar();
               addProgressBar();
               terminal.flush();
-              if (!cursorControl) {
-                // If we can't update the progress bar in place, make sure we increase the update
-                // interval as time progresses, to avoid too many progress messages in place.
-                minimalDelayMillis =
-                    Math.max(
-                        minimalDelayMillis,
-                        Math.round(
-                            NO_CURSES_MINIMAL_RELATIVE_PROGRESS_RATE_LMIT
-                                * (clock.currentTimeMillis() - uiStartTimeMillis)));
-                minimalUpdateInterval = Math.max(minimalDelayMillis, MAXIMAL_UPDATE_DELAY_MILLIS);
-              }
             }
           }
         } catch (IOException e) {
@@ -901,7 +882,7 @@ private void refreshSoon() {
     // a future update scheduled.
     long nowMillis = clock.currentTimeMillis();
     if (mustRefreshAfterMillis <= lastRefreshMillis) {
-      mustRefreshAfterMillis = Math.max(nowMillis + minimalUpdateInterval, lastRefreshMillis + 1);
+      mustRefreshAfterMillis = Math.max(nowMillis + 1, lastRefreshMillis + minimalUpdateInterval);
     }
     startUpdateThread();
   }
@@ -911,22 +892,25 @@ private synchronized boolean timeBasedRefresh() {
     if (!stateTracker.progressBarTimeDependent()) {
       return false;
     }
+    // Don't do more updates than are requested through events when there is no cursor control.
+    if (!cursorControl) {
+      return false;
+    }
     long nowMillis = clock.currentTimeMillis();
-    long intervalMillis = cursorControl ? SHORT_REFRESH_MILLIS : LONG_REFRESH_MILLIS;
     if (lastRefreshMillis < mustRefreshAfterMillis
-        && mustRefreshAfterMillis < nowMillis + minimalDelayMillis) {
-      // Within the small interval from now, an update is scheduled anyway,
+        && mustRefreshAfterMillis < nowMillis + progressRateLimitMillis) {
+      // Within a small interval from now, an update is scheduled anyway,
       // so don't do a time-based update of the progress bar now, to avoid
       // updates too close to each other.
       return false;
     }
-    return lastRefreshMillis + intervalMillis < nowMillis;
+    return lastRefreshMillis + SHORT_REFRESH_MILLIS < nowMillis;
   }
 
   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;
+    lastRefreshMillis = clock.currentTimeMillis() - progressRateLimitMillis - 1;
   }
 
   private void startUpdateThread() {
