UI: distinguish executing actions
When showing the current actions, the most interesting are those
that are currently being executed, not those that are waiting for
resources or otherwise in the process of being scheduled. Therefore,
show the executing actions at the top of the list. Also add more
visual hints to distinguish executing from non executing actions.
Screenshot
(14:51:21) [160 / 230] 32 actions, 11 running
Compiling lotsofwork/true986.c; 0s linux-sandbox
Compiling lotsofwork/true982.c; 0s linux-sandbox
Compiling lotsofwork/true983.c; 0s linux-sandbox
Executing genrule //lotsofwork:true975_c; 0s linux-sandbox
Compiling lotsofwork/true981.c; 0s linux-sandbox
Linking lotsofwork/true_999; 0s linux-sandbox
Linking lotsofwork/true_996; 0s linux-sandbox
Linking lotsofwork/true_998; 0s linux-sandbox
Compiling lotsofwork/true980.c; 0s linux-sandbox
Compiling lotsofwork/true98.c; 0s linux-sandbox
Executing genrule //lotsofwork:true974_c; 0s linux-sandbox
[Sched] Creating runfiles tree bazel-out/k8-fastbuild/bin/lotsofwork/true_974.runfiles
[Sched] Linking lotsofwork/true_997
[Sched] Linking lotsofwork/true_995
[Sched] Linking lotsofwork/true_99
[Sched] Linking lotsofwork/true_991 ...
Improves on #4089.
Change-Id: I1bc6636d5e53a16151023bba595e38259eb1ac88
PiperOrigin-RevId: 176483192
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 5df6a8d..1995ebd 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
@@ -48,6 +48,7 @@
import java.util.Set;
import java.util.TreeMap;
import java.util.TreeSet;
+import java.util.stream.Stream;
/**
* An experimental state tracker for the new experimental UI.
@@ -58,7 +59,8 @@
static final String ELLIPSIS = "...";
static final String FETCH_PREFIX = " Fetching ";
static final String AND_MORE = " ...";
-
+ static final String NO_STATUS = "-----";
+ static final int STATUS_LENGTH = 5;
static final int NANOS_PER_SECOND = 1000000000;
static final String URL_PROTOCOL_SEP = "://";
@@ -79,7 +81,8 @@
private final Deque<String> runningActions;
private final Map<String, Action> actions;
private final Map<String, Long> actionNanoStartTimes;
- private final Map<String, String> actionStrategy;
+ private final Map<String, String> actionStatus;
+ private final Set<String> executingActions;
// running downloads are identified by the original URL they were trying to
// access.
@@ -112,8 +115,9 @@
ExperimentalStateTracker(Clock clock, int targetWidth) {
this.runningActions = new ArrayDeque<>();
this.actions = new TreeMap<>();
+ this.executingActions = new TreeSet<>();
this.actionNanoStartTimes = new TreeMap<>();
- this.actionStrategy = new TreeMap<>();
+ this.actionStatus = new TreeMap<>();
this.testActions = new TreeMap<>();
this.runningDownloads = new ArrayDeque<>();
this.downloads = new TreeMap<>();
@@ -248,12 +252,14 @@
String name = event.getActionMetadata().getPrimaryOutput().getPath().getPathString();
if (strategy != null) {
synchronized (this) {
- actionStrategy.put(name, strategy);
+ actionStatus.put(name, strategy);
+ executingActions.add(name);
}
} else {
String message = event.getMessage();
synchronized (this) {
- actionStrategy.put(name, message);
+ actionStatus.put(name, message);
+ executingActions.remove(name);
}
}
}
@@ -263,9 +269,10 @@
Action action = event.getAction();
String name = action.getPrimaryOutput().getPath().getPathString();
runningActions.remove(name);
+ executingActions.remove(name);
actions.remove(name);
actionNanoStartTimes.remove(name);
- actionStrategy.remove(name);
+ actionStatus.remove(name);
if (action.getOwner() != null) {
Label owner = action.getOwner().getLabel();
@@ -393,9 +400,22 @@
}
String postfix = "";
+ String prefix = "";
long nanoRuntime = nanoTime - actionNanoStartTimes.get(name);
long runtimeSeconds = nanoRuntime / NANOS_PER_SECOND;
- String strategy = actionStrategy.get(name);
+ String strategy = null;
+ if (executingActions.contains(name)) {
+ strategy = actionStatus.get(name);
+ } else {
+ String status = actionStatus.get(name);
+ if (status == null) {
+ status = NO_STATUS;
+ }
+ if (status.length() > STATUS_LENGTH) {
+ status = status.substring(0, STATUS_LENGTH);
+ }
+ prefix = prefix + "[" + status + "] ";
+ }
// To keep the UI appearance more stable, always show the elapsed
// time if we also show a strategy (otherwise the strategy will jump in
// the progress bar).
@@ -412,10 +432,10 @@
}
if (desiredWidth <= 0) {
- return message + postfix;
+ return prefix + message + postfix;
}
- if (message.length() + postfix.length() <= desiredWidth) {
- return message + postfix;
+ if (prefix.length() + message.length() + postfix.length() <= desiredWidth) {
+ return prefix + message + postfix;
}
// We have to shorten the message to fit into the line.
@@ -428,31 +448,56 @@
if (pathIndex >= 0) {
String start = message.substring(0, pathIndex);
String end = message.substring(pathIndex + pathString.length());
- int pathTargetLength = desiredWidth - start.length() - end.length() - postfix.length();
+ int pathTargetLength =
+ desiredWidth - start.length() - end.length() - postfix.length() - prefix.length();
// This attempt of shortening is reasonable if what is left from the label
// is significantly longer (twice as long) as the ellipsis symbols introduced.
if (pathTargetLength >= 3 * ELLIPSIS.length()) {
String shortPath = suffix(pathString, pathTargetLength - ELLIPSIS.length());
int slashPos = shortPath.indexOf('/');
if (slashPos >= 0) {
- return start + ELLIPSIS + shortPath.substring(slashPos) + end + postfix;
+ return prefix + start + ELLIPSIS + shortPath.substring(slashPos) + end + postfix;
}
}
}
// Second attempt: just take a shortened version of the label.
String shortLabel =
- shortenedLabelString(action.getOwner().getLabel(), desiredWidth - postfix.length());
- if (shortLabel.length() + postfix.length() <= desiredWidth) {
- return shortLabel + postfix;
+ shortenedLabelString(
+ action.getOwner().getLabel(), desiredWidth - postfix.length() - prefix.length());
+ if (prefix.length() + shortLabel.length() + postfix.length() <= desiredWidth) {
+ return prefix + shortLabel + postfix;
}
}
}
- if (3 * ELLIPSIS.length() + postfix.length() <= desiredWidth) {
- message = ELLIPSIS + suffix(message, desiredWidth - ELLIPSIS.length() - postfix.length());
+ if (3 * ELLIPSIS.length() + postfix.length() + prefix.length() <= desiredWidth) {
+ message =
+ ELLIPSIS
+ + suffix(
+ message, desiredWidth - ELLIPSIS.length() - postfix.length() - prefix.length());
}
- return message + postfix;
+ return prefix + message + postfix;
+ }
+
+ /**
+ * Stream of actions in decreasing order of importance for the UI. I.e., first have all executing
+ * actions and then all non-executing actions, each time in order of increasing start time.
+ */
+ private Stream<String> sortedActions() {
+ return Stream.concat(
+ runningActions.stream().filter(s -> executingActions.contains(s)),
+ runningActions.stream().filter(s -> !executingActions.contains(s)));
+ }
+
+ private String countActions() {
+ if (runningActions.size() == 1) {
+ return " 1 action";
+ } else if (runningActions.size() == executingActions.size()) {
+ return "" + runningActions.size() + " actions running";
+ } else {
+ return "" + runningActions.size() + " actions, " + executingActions.size() + " running";
+ }
}
private void sampleOldestActions(AnsiTerminalWriter terminalWriter) throws IOException {
@@ -461,7 +506,7 @@
long nanoTime = clock.nanoTime();
int actionCount = runningActions.size();
Set<String> toSkip = new TreeSet<>();
- for (String action : runningActions) {
+ for (String action : (Iterable<String>) sortedActions()::iterator) {
totalCount++;
if (toSkip.contains(action)) {
continue;
@@ -767,14 +812,14 @@
if (shortVersion) {
String statusMessage =
describeAction(
- runningActions.peekFirst(),
+ sortedActions().findFirst().get(),
clock.nanoTime(),
targetWidth - terminalWriter.getPosition(),
null);
- statusMessage += " ... (" + runningActions.size() + " actions)";
+ statusMessage += " ... (" + countActions() + ")";
terminalWriter.normal().append(" " + statusMessage);
} else {
- String statusMessage = "" + runningActions.size() + " actions";
+ String statusMessage = countActions();
terminalWriter.normal().append(" " + statusMessage);
maybeShowRecentTest(
terminalWriter, shortVersion, targetWidth - terminalWriter.getPosition());
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 d827f64..6307ff8 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
@@ -557,6 +557,113 @@
}
@Test
+ public void testStatusShown() throws Exception {
+ // Verify that for non-executing actions, at least the first 3 characters of the
+ // status are shown.
+ // Also verify that the number of running actions is reported correctly, if there is
+ // more than one active action and not all are running.
+ ManualClock clock = new ManualClock();
+ clock.advanceMillis(120000);
+ ExperimentalStateTracker stateTracker = new ExperimentalStateTracker(clock);
+ Action actionFoo = mockAction("Building foo", "foo/foo");
+ ActionOwner ownerFoo = Mockito.mock(ActionOwner.class);
+ when(actionFoo.getOwner()).thenReturn(ownerFoo);
+ Action actionBar = mockAction("Building bar", "bar/bar");
+ ActionOwner ownerBar = Mockito.mock(ActionOwner.class);
+ when(actionBar.getOwner()).thenReturn(ownerBar);
+ LoggingTerminalWriter terminalWriter;
+ String output;
+
+ // Action foo being analyzed.
+ stateTracker.actionStarted(new ActionStartedEvent(actionFoo, 123456700));
+ stateTracker.actionStatusMessage(ActionStatusMessage.analysisStrategy(actionFoo));
+
+ terminalWriter = new LoggingTerminalWriter(/*discardHighlight=*/ true);
+ stateTracker.writeProgressBar(terminalWriter);
+ output = terminalWriter.getTranscript();
+ assertWithMessage("Action foo being analyzed should be visible in output:\n" + output)
+ .that(output.contains("ana") || output.contains("Ana"))
+ .isTrue();
+
+ // Then action bar gets scheduled.
+ stateTracker.actionStarted(new ActionStartedEvent(actionBar, 123456701));
+ stateTracker.actionStatusMessage(ActionStatusMessage.schedulingStrategy(actionBar));
+
+ terminalWriter = new LoggingTerminalWriter(/*discardHighlight=*/ true);
+ stateTracker.writeProgressBar(terminalWriter);
+ output = terminalWriter.getTranscript();
+ assertWithMessage("Action bar being scheduled should be visible in output:\n" + output)
+ .that(output.contains("sch") || output.contains("Sch"))
+ .isTrue();
+ assertWithMessage("Action foo being analyzed should still be visible in output:\n" + output)
+ .that(output.contains("ana") || output.contains("Ana"))
+ .isTrue();
+ assertWithMessage("Indication at no actions are running is missing in output:\n" + output)
+ .that(output.contains("0 running"))
+ .isTrue();
+ assertWithMessage("Total number of actions expected in output:\n" + output)
+ .that(output.contains("2 actions"))
+ .isTrue();
+
+ // Then foo starts.
+ stateTracker.actionStatusMessage(ActionStatusMessage.runningStrategy(actionFoo, "xyz-sandbox"));
+ stateTracker.writeProgressBar(terminalWriter);
+
+ terminalWriter = new LoggingTerminalWriter(/*discardHighlight=*/ true);
+ stateTracker.writeProgressBar(terminalWriter);
+ output = terminalWriter.getTranscript();
+ assertWithMessage("Action foo's xyz-sandbox strategy should be shown in output:\n" + output)
+ .that(output.contains("xyz-sandbox"))
+ .isTrue();
+ assertWithMessage("Action foo should no longer be analyzed in output:\n" + output)
+ .that(output.contains("ana") || output.contains("Ana"))
+ .isFalse();
+ assertWithMessage("Action bar being scheduled should still be visible in output:\n" + output)
+ .that(output.contains("sch") || output.contains("Sch"))
+ .isTrue();
+ assertWithMessage("Indication at one action is running is missing in output:\n" + output)
+ .that(output.contains("1 running"))
+ .isTrue();
+ assertWithMessage("Total number of actions expected in output:\n" + output)
+ .that(output.contains("2 actions"))
+ .isTrue();
+ }
+
+ @Test
+ public void testExecutingActionsFirst() throws Exception {
+ // Verify that executing actions, even if started late, are visible.
+ ManualClock clock = new ManualClock();
+ ExperimentalStateTracker stateTracker = new ExperimentalStateTracker(clock);
+ clock.advanceMillis(120000);
+
+ for (int i = 0; i < 30; i++) {
+ Action action = mockAction("Takes long to schedule number " + i, "long/startup" + i);
+ ActionOwner owner = Mockito.mock(ActionOwner.class);
+ when(action.getOwner()).thenReturn(owner);
+ stateTracker.actionStarted(new ActionStartedEvent(action, 123456789 + i));
+ stateTracker.actionStatusMessage(ActionStatusMessage.schedulingStrategy(action));
+ }
+
+ for (int i = 0; i < 3; i++) {
+ Action action = mockAction("quickstart" + i, "pkg/quickstart" + i);
+ ActionOwner owner = Mockito.mock(ActionOwner.class);
+ when(action.getOwner()).thenReturn(owner);
+ stateTracker.actionStarted(new ActionStartedEvent(action, 123457000 + i));
+ stateTracker.actionStatusMessage(ActionStatusMessage.runningStrategy(action, "xyz-sandbox"));
+
+ LoggingTerminalWriter terminalWriter = new LoggingTerminalWriter(/*discardHighlight=*/ true);
+ stateTracker.writeProgressBar(terminalWriter);
+ String output = terminalWriter.getTranscript();
+ assertWithMessage("Action quickstart" + i + " should be visible in output:\n" + output)
+ .that(output.contains("quickstart" + i))
+ .isTrue();
+ assertWithMessage("Number of running actions should be indicated in output:\n" + output)
+ .that(output.contains("" + (i + 1) + " running"))
+ .isTrue();
+ }
+ }
+
+ @Test
public void testAggregation() throws Exception {
// Assert that actions for the same test are aggregated so that an action afterwards
// is still shown.
