// 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.runtime; import com.google.devtools.build.lib.actions.Action; import com.google.devtools.build.lib.actions.ActionCompletionEvent; import com.google.devtools.build.lib.actions.ActionStartedEvent; import com.google.devtools.build.lib.actions.ActionStatusMessage; import com.google.devtools.build.lib.analysis.AnalysisPhaseCompleteEvent; import com.google.devtools.build.lib.analysis.ConfiguredTarget; import com.google.devtools.build.lib.buildtool.ExecutionProgressReceiver; import com.google.devtools.build.lib.buildtool.buildevent.BuildCompleteEvent; import com.google.devtools.build.lib.buildtool.buildevent.BuildStartingEvent; import com.google.devtools.build.lib.buildtool.buildevent.ExecutionProgressReceiverAvailableEvent; import com.google.devtools.build.lib.buildtool.buildevent.TestFilteringCompleteEvent; 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.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; import java.io.IOException; import java.util.ArrayDeque; import java.util.Deque; import java.util.LinkedHashSet; import java.util.Map; import java.util.Set; import java.util.TreeMap; import java.util.TreeSet; /** * An experimental state tracker for the new experimental UI. */ class ExperimentalStateTracker { static final long SHOW_TIME_THRESHOLD_SECONDS = 3; static final String ELLIPSIS = "..."; static final int NANOS_PER_SECOND = 1000000000; private int sampleSize = 3; private String status; private String additionalMessage; private final Clock clock; // Desired maximal width of the progress bar, if positive. // Non-positive values indicate not to aim for a particular width. private final int targetWidth; // currently running actions, using the path of the primary // output as unique identifier. private final Deque runningActions; private final Map actions; private final Map actionNanoStartTimes; private final Map actionStrategy; // For each test, the list of actions (again identified by the path of the // primary output) currently running for that test (identified by its label), // in order they got started. A key is present in the map if and only if that // was discovered as a test. private final Map> testActions; private int actionsCompleted; private int totalTests; private int completedTests; private TestSummary mostRecentTest; private int failedTests; private boolean ok; private ExecutionProgressReceiver executionProgressReceiver; private PackageProgressReceiver packageProgressReceiver; ExperimentalStateTracker(Clock clock, int targetWidth) { this.runningActions = new ArrayDeque<>(); this.actions = new TreeMap<>(); this.actionNanoStartTimes = new TreeMap<>(); this.actionStrategy = new TreeMap<>(); this.testActions = new TreeMap<>(); this.ok = true; this.clock = clock; this.targetWidth = targetWidth; } ExperimentalStateTracker(Clock clock) { this(clock, 0); } /** * Set the maximal number of actions shown in the progress bar. */ void setSampleSize(int sampleSize) { if (sampleSize >= 1) { this.sampleSize = sampleSize; } else { this.sampleSize = 1; } } void buildStarted(BuildStartingEvent event) { status = "Loading"; additionalMessage = ""; } void loadingStarted(LoadingPhaseStartedEvent event) { status = null; packageProgressReceiver = event.getPackageProgressReceiver(); } void loadingComplete(LoadingPhaseCompleteEvent event) { int count = event.getTargets().size(); status = "Analyzing"; if (count == 1) { additionalMessage = "target " + event.getTargets().asList().get(0).getLabel(); } else { additionalMessage = "" + count + " targets"; } } /** * Make the state tracker aware of the fact that the analyis has finished. Return a summary of the * work done in the analysis phase. */ synchronized String analysisComplete(AnalysisPhaseCompleteEvent event) { String workDone = "Analysed " + additionalMessage; if (packageProgressReceiver != null) { Pair progress = packageProgressReceiver.progressState(); workDone += " (" + progress.getFirst() + ")"; } workDone += "."; status = null; packageProgressReceiver = null; return workDone; } void progressReceiverAvailable(ExecutionProgressReceiverAvailableEvent event) { executionProgressReceiver = event.getExecutionProgressReceiver(); } void buildComplete(BuildCompleteEvent event, String additionalInfo) { if (event.getResult().getSuccess()) { status = "INFO"; if (failedTests == 0) { additionalMessage = additionalInfo + "Build completed successfully, " + actionsCompleted + " total action" + (actionsCompleted == 1 ? "" : "s"); } else { additionalMessage = additionalInfo + "Build completed, " + failedTests + " test" + (failedTests == 1 ? "" : "s") + " FAILED, " + actionsCompleted + " total action" + (actionsCompleted == 1 ? "" : "s"); } } else { ok = false; status = "FAILED"; additionalMessage = additionalInfo + "Build did NOT complete successfully"; } } void buildComplete(BuildCompleteEvent event) { buildComplete(event, ""); } synchronized void actionStarted(ActionStartedEvent event) { Action action = event.getAction(); String name = action.getPrimaryOutput().getPath().getPathString(); Long nanoStartTime = event.getNanoTimeStart(); runningActions.addLast(name); actions.put(name, action); actionNanoStartTimes.put(name, nanoStartTime); if (action.getOwner() != null) { Label owner = action.getOwner().getLabel(); if (owner != null) { Set testActionsForOwner = testActions.get(owner); if (testActionsForOwner != null) { testActionsForOwner.add(name); } } } } void actionStatusMessage(ActionStatusMessage event) { String strategy = event.getStrategy(); if (strategy != null) { String name = event.getActionMetadata().getPrimaryOutput().getPath().getPathString(); synchronized (this) { actionStrategy.put(name, strategy); } } } synchronized void actionCompletion(ActionCompletionEvent event) { actionsCompleted++; Action action = event.getAction(); String name = action.getPrimaryOutput().getPath().getPathString(); runningActions.remove(name); actions.remove(name); actionNanoStartTimes.remove(name); actionStrategy.remove(name); if (action.getOwner() != null) { Label owner = action.getOwner().getLabel(); if (owner != null) { Set testActionsForOwner = testActions.get(owner); if (testActionsForOwner != null) { testActionsForOwner.remove(name); } } } // As callers to the experimental state tracker assume we will fully report the new state once // informed of an action completion, we need to make sure the progress receiver is aware of the // completion, even though it might be called later on the event bus. if (executionProgressReceiver != null) { executionProgressReceiver.actionCompleted(action); } } /** * From a string, take a suffix of at most the given length. */ static String suffix(String s, int len) { if (len <= 0) { return ""; } int startPos = s.length() - len; if (startPos <= 0) { return s; } return s.substring(startPos); } /** * If possible come up with a human-readable description of the label * that fits within the given width; a non-positive width indicates not * no restriction at all. */ private String shortenedLabelString(Label label, int width) { if (width <= 0) { return label.toString(); } String name = label.toString(); if (name.length() <= width) { return name; } name = suffix(name, width - ELLIPSIS.length()); int slashPos = name.indexOf('/'); if (slashPos >= 0) { return ELLIPSIS + name.substring(slashPos); } int colonPos = name.indexOf(':'); if (slashPos >= 0) { return ELLIPSIS + name.substring(colonPos); } // no reasonable place found to shorten; as last resort, just truncate if (3 * ELLIPSIS.length() <= width) { return ELLIPSIS + suffix(label.toString(), width - ELLIPSIS.length()); } return label.toString(); } // Describe a group of actions running for the same test. private String describeTestGroup( Label owner, long nanoTime, int desiredWidth, Set allActions) { String prefix = "Testing "; String labelSep = " ["; String postfix = " (" + allActions.size() + " actions)]"; // Leave enough room for at least 3 samples of run times, each 4 characters // (a digit, 's', comma, and space). int labelWidth = desiredWidth - prefix.length() - labelSep.length() - postfix.length() - 12; StringBuffer message = new StringBuffer(prefix).append(shortenedLabelString(owner, labelWidth)).append(labelSep); // Compute the remaining width for the sample times, but if the desired width is too small // anyway, then show at least one sample. int remainingWidth = desiredWidth - message.length() - postfix.length(); if (remainingWidth < 0) { remainingWidth = 5; } String sep = ""; int count = 0; for (String action : allActions) { long nanoRuntime = nanoTime - actionNanoStartTimes.get(action); long runtimeSeconds = nanoRuntime / NANOS_PER_SECOND; String text = sep + runtimeSeconds + "s"; if (remainingWidth < text.length()) { break; } message.append(text); remainingWidth -= text.length(); count++; sep = ", "; } if (count == allActions.size()) { postfix = "]"; } return message.append(postfix).toString(); } // Describe an action by a string of the desired length; if describing that action includes // describing other actions, add those to the to set of actions to skip in further samples of // actions. private String describeAction(String name, long nanoTime, int desiredWidth, Set toSkip) { Action action = actions.get(name); if (action.getOwner() != null) { Label owner = action.getOwner().getLabel(); if (owner != null) { Set allRelatedActions = testActions.get(owner); if (allRelatedActions != null && allRelatedActions.size() > 1) { if (toSkip != null) { toSkip.addAll(allRelatedActions); } return describeTestGroup(owner, nanoTime, desiredWidth, allRelatedActions); } } } String postfix = ""; long nanoRuntime = nanoTime - actionNanoStartTimes.get(name); long runtimeSeconds = nanoRuntime / NANOS_PER_SECOND; String strategy = actionStrategy.get(name); // 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). if (strategy != null || runtimeSeconds > SHOW_TIME_THRESHOLD_SECONDS) { postfix = "; " + runtimeSeconds + "s"; } if (strategy != null) { postfix += " " + strategy; } String message = action.getProgressMessage(); if (message == null) { message = action.prettyPrint(); } if (desiredWidth <= 0) { return message + postfix; } if (message.length() + postfix.length() <= desiredWidth) { return message + postfix; } // We have to shorten the message to fit into the line. if (action.getOwner() != null) { if (action.getOwner().getLabel() != null) { // First attempt is to shorten the package path string in the messge, if it occurs there String pathString = action.getOwner().getLabel().getPackageFragment().toString(); int pathIndex = message.indexOf(pathString); 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(); // 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; } } } // 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; } } } if (3 * ELLIPSIS.length() + postfix.length() <= desiredWidth) { message = ELLIPSIS + suffix(message, desiredWidth - ELLIPSIS.length() - postfix.length()); } return message + postfix; } private void sampleOldestActions(AnsiTerminalWriter terminalWriter) throws IOException { int count = 0; int totalCount = 0; long nanoTime = clock.nanoTime(); int actionCount = runningActions.size(); Set toSkip = new TreeSet<>(); for (String action : runningActions) { totalCount++; if (toSkip.contains(action)) { continue; } count++; if (count > sampleSize) { totalCount--; break; } int width = (count >= sampleSize && count < actionCount) ? targetWidth - 8 : targetWidth - 4; terminalWriter.newline().append(" " + describeAction(action, nanoTime, width, toSkip)); } if (totalCount < actionCount) { terminalWriter.append(" ..."); } } public synchronized void testFilteringComplete(TestFilteringCompleteEvent event) { if (event.getTestTargets() != null) { totalTests = event.getTestTargets().size(); for (ConfiguredTarget target : event.getTestTargets()) { if (target.getLabel() != null) { testActions.put(target.getLabel(), new LinkedHashSet()); } } } } public synchronized void testSummary(TestSummary summary) { completedTests++; mostRecentTest = summary; if (summary.getStatus() != BlazeTestStatus.PASSED) { failedTests++; } } /*** * Predicate indicating whether the contents of the progress bar can change, if the * only thing that happens is that time passes; this is the case, e.g., if the progress * bar shows time information relative to the current time. */ boolean progressBarTimeDependent() { if (packageProgressReceiver != null) { return true; } if (status != null) { return false; } if (runningActions.size() >= 1) { return true; } return false; } /** * Maybe add a note about the last test that passed. Return true, if the note was added (and * hence a line break is appropriate if more data is to come. If a null value is provided for * the terminal writer, only return wether a note would be added. * * The width parameter gives advice on to which length the the description of the test should * the shortened to, if possible. */ private boolean maybeShowRecentTest( AnsiTerminalWriter terminalWriter, boolean shortVersion, int width) throws IOException { final String prefix = "; last test: "; if (!shortVersion && mostRecentTest != null) { if (terminalWriter != null) { terminalWriter.normal().append(prefix); if (mostRecentTest.getStatus() == BlazeTestStatus.PASSED) { terminalWriter.okStatus(); } else { terminalWriter.failStatus(); } terminalWriter.append( shortenedLabelString(mostRecentTest.getTarget().getLabel(), width - prefix.length())); terminalWriter.normal(); } return true; } else { return false; } } synchronized void writeProgressBar(AnsiTerminalWriter rawTerminalWriter, boolean shortVersion) throws IOException { PositionAwareAnsiTerminalWriter terminalWriter = new PositionAwareAnsiTerminalWriter(rawTerminalWriter); if (status != null) { if (ok) { terminalWriter.okStatus(); } else { terminalWriter.failStatus(); } terminalWriter.append(status + ":").normal().append(" " + additionalMessage); if (packageProgressReceiver != null) { Pair progress = packageProgressReceiver.progressState(); terminalWriter.append(" (" + progress.getFirst() + ")"); if (progress.getSecond().length() > 0 && !shortVersion) { terminalWriter.newline().append(" " + progress.getSecond()); } } return; } if (packageProgressReceiver != null) { Pair 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) { terminalWriter.okStatus().append(executionProgressReceiver.getProgressString()); } else { terminalWriter.okStatus().append("Building:"); } if (completedTests > 0) { terminalWriter.normal().append(" " + completedTests + " / " + totalTests + " tests"); if (failedTests > 0) { terminalWriter.append(", ").failStatus().append("" + failedTests + " failed").normal(); } terminalWriter.append(";"); } if (runningActions.size() == 0) { terminalWriter.normal().append(" no action running"); maybeShowRecentTest(terminalWriter, shortVersion, targetWidth - terminalWriter.getPosition()); } else if (runningActions.size() == 1) { if (maybeShowRecentTest(null, shortVersion, targetWidth - terminalWriter.getPosition())) { // As we will break lines anyway, also show the number of running actions, to keep // things stay roughly in the same place (also compensating for the missing plural-s // in the word action). terminalWriter.normal().append(" 1 action running"); maybeShowRecentTest( terminalWriter, shortVersion, targetWidth - terminalWriter.getPosition()); String statusMessage = describeAction(runningActions.peekFirst(), clock.nanoTime(), targetWidth - 4, null); terminalWriter.normal().newline().append(" " + statusMessage); } else { String statusMessage = describeAction( runningActions.peekFirst(), clock.nanoTime(), targetWidth - terminalWriter.getPosition() - 1, null); terminalWriter.normal().append(" " + statusMessage); } } else { if (shortVersion) { String statusMessage = describeAction( runningActions.peekFirst(), clock.nanoTime(), targetWidth - terminalWriter.getPosition(), null); statusMessage += " ... (" + runningActions.size() + " actions running)"; terminalWriter.normal().append(" " + statusMessage); } else { String statusMessage = "" + runningActions.size() + " actions running"; terminalWriter.normal().append(" " + statusMessage); maybeShowRecentTest( terminalWriter, shortVersion, targetWidth - terminalWriter.getPosition()); sampleOldestActions(terminalWriter); } } } void writeProgressBar(AnsiTerminalWriter terminalWriter) throws IOException { writeProgressBar(terminalWriter, false); } }