blob: 9a12eb1345707ddcd7858a7ac490a56ab7d141c8 [file] [log] [blame]
Klaus Aehlig8cad4bd2016-03-14 11:13:58 +00001// Copyright 2016 The Bazel Authors. All rights reserved.
2//
3// Licensed under the Apache License, Version 2.0 (the "License");
4// you may not use this file except in compliance with the License.
5// You may obtain a copy of the License at
6//
7// http://www.apache.org/licenses/LICENSE-2.0
8//
9// Unless required by applicable law or agreed to in writing, software
10// distributed under the License is distributed on an "AS IS" BASIS,
11// WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
12// See the License for the specific language governing permissions and
13// limitations under the License.
14package com.google.devtools.build.lib.runtime;
15
16import static org.junit.Assert.assertFalse;
17import static org.junit.Assert.assertTrue;
18import static org.mockito.Mockito.when;
19
Klaus Aehligd232d232016-04-13 09:51:25 +000020import com.google.common.collect.ImmutableSet;
Klaus Aehlig8cad4bd2016-03-14 11:13:58 +000021import com.google.devtools.build.lib.actions.Action;
22import com.google.devtools.build.lib.actions.ActionCompletionEvent;
23import com.google.devtools.build.lib.actions.ActionStartedEvent;
24import com.google.devtools.build.lib.actions.Artifact;
25import com.google.devtools.build.lib.actions.Root;
Klaus Aehligd232d232016-04-13 09:51:25 +000026import com.google.devtools.build.lib.analysis.ConfiguredTarget;
27import com.google.devtools.build.lib.buildtool.buildevent.TestFilteringCompleteEvent;
Klaus Aehligb8d0c6b2016-04-13 11:06:41 +000028import com.google.devtools.build.lib.cmdline.Label;
Klaus Aehlig8cad4bd2016-03-14 11:13:58 +000029import com.google.devtools.build.lib.testutil.FoundationTestCase;
Klaus Aehliged453e02016-04-15 11:29:05 +000030import com.google.devtools.build.lib.testutil.LoggingTerminalWriter;
Klaus Aehliga63d9612016-04-04 12:15:23 +000031import com.google.devtools.build.lib.testutil.ManualClock;
Klaus Aehlig8cad4bd2016-03-14 11:13:58 +000032import com.google.devtools.build.lib.vfs.Path;
33import com.google.devtools.build.lib.vfs.PathFragment;
Klaus Aehligb8d0c6b2016-04-13 11:06:41 +000034import com.google.devtools.build.lib.view.test.TestStatus.BlazeTestStatus;
Klaus Aehlig8cad4bd2016-03-14 11:13:58 +000035
36import org.junit.Test;
37import org.junit.runner.RunWith;
38import org.junit.runners.JUnit4;
39import org.mockito.Mockito;
40
41import java.io.IOException;
Klaus Aehlige25642a2016-04-04 13:31:28 +000042import java.util.concurrent.TimeUnit;
Klaus Aehlig8cad4bd2016-03-14 11:13:58 +000043
44/**
Klaus Aehligc23ba452016-04-06 12:16:39 +000045 * Tests {@link ExperimentalStateTracker}.
Klaus Aehlig8cad4bd2016-03-14 11:13:58 +000046 */
47@RunWith(JUnit4.class)
48public class ExperimentalStateTrackerTest extends FoundationTestCase {
49
50 private Action mockAction(String progressMessage, String primaryOutput) {
51 Path path = outputBase.getRelative(new PathFragment(primaryOutput));
52 Artifact artifact = new Artifact(path, Root.asSourceRoot(path));
53
54 Action action = Mockito.mock(Action.class);
55 when(action.getProgressMessage()).thenReturn(progressMessage);
56 when(action.getPrimaryOutput()).thenReturn(artifact);
57 return action;
58 }
59
Klaus Aehlig6d0876a2016-04-15 14:41:07 +000060 private int longestLine(String output) {
61 int maxLength = 0;
62 for (String line : output.split("\n")) {
63 maxLength = Math.max(maxLength, line.length());
64 }
65 return maxLength;
66 }
67
Klaus Aehlig8cad4bd2016-03-14 11:13:58 +000068 @Test
69 public void testActionVisible() throws IOException {
70 // If there is only one action running, it should be visible
Klaus Aehligc0c88842016-04-11 12:07:38 +000071 // somewhere in the progress bar, and also the short version thereof.
Klaus Aehlig8cad4bd2016-03-14 11:13:58 +000072
73 String message = "Building foo";
Klaus Aehliga63d9612016-04-04 12:15:23 +000074 ManualClock clock = new ManualClock();
75 clock.advanceMillis(120000);
Klaus Aehlig8cad4bd2016-03-14 11:13:58 +000076
Klaus Aehliga63d9612016-04-04 12:15:23 +000077 ExperimentalStateTracker stateTracker = new ExperimentalStateTracker(clock);
Klaus Aehlig8cad4bd2016-03-14 11:13:58 +000078 stateTracker.actionStarted(new ActionStartedEvent(mockAction(message, "bar/foo"), 123456789));
Klaus Aehligc0c88842016-04-11 12:07:38 +000079
Klaus Aehliged453e02016-04-15 11:29:05 +000080 LoggingTerminalWriter terminalWriter = new LoggingTerminalWriter(/*discardHighlight=*/ true);
Klaus Aehlig8cad4bd2016-03-14 11:13:58 +000081 stateTracker.writeProgressBar(terminalWriter);
Klaus Aehliged453e02016-04-15 11:29:05 +000082 String output = terminalWriter.getTranscript();
Klaus Aehlig8cad4bd2016-03-14 11:13:58 +000083 assertTrue(
84 "Action message '" + message + "' should be present in output: " + output,
85 output.contains(message));
Klaus Aehligc0c88842016-04-11 12:07:38 +000086
87 terminalWriter = new LoggingTerminalWriter();
88 stateTracker.writeProgressBar(terminalWriter, /* shortVersion=*/ true);
Klaus Aehliged453e02016-04-15 11:29:05 +000089 output = terminalWriter.getTranscript();
Klaus Aehligc0c88842016-04-11 12:07:38 +000090 assertTrue(
91 "Action message '" + message + "' should be present in short output: " + output,
92 output.contains(message));
93
Klaus Aehlig8cad4bd2016-03-14 11:13:58 +000094 }
95
96 @Test
97 public void testCompletedActionNotShown() throws IOException {
Klaus Aehligc0c88842016-04-11 12:07:38 +000098 // Completed actions should not be reported in the progress bar, nor in the
99 // short progress bar.
Klaus Aehlig8cad4bd2016-03-14 11:13:58 +0000100
101 String messageFast = "Running quick action";
102 String messageSlow = "Running slow action";
103
Klaus Aehliga63d9612016-04-04 12:15:23 +0000104 ManualClock clock = new ManualClock();
105 clock.advanceMillis(120000);
Klaus Aehlig8cad4bd2016-03-14 11:13:58 +0000106 Action fastAction = mockAction(messageFast, "foo/fast");
107 Action slowAction = mockAction(messageSlow, "bar/slow");
Klaus Aehliga63d9612016-04-04 12:15:23 +0000108 ExperimentalStateTracker stateTracker = new ExperimentalStateTracker(clock);
Klaus Aehlig8cad4bd2016-03-14 11:13:58 +0000109 stateTracker.actionStarted(new ActionStartedEvent(fastAction, 123456789));
110 stateTracker.actionStarted(new ActionStartedEvent(slowAction, 123456999));
111 stateTracker.actionCompletion(new ActionCompletionEvent(20, fastAction));
112
Klaus Aehliged453e02016-04-15 11:29:05 +0000113 LoggingTerminalWriter terminalWriter = new LoggingTerminalWriter(/*discardHighlight=*/ true);
Klaus Aehlig8cad4bd2016-03-14 11:13:58 +0000114 stateTracker.writeProgressBar(terminalWriter);
Klaus Aehliged453e02016-04-15 11:29:05 +0000115 String output = terminalWriter.getTranscript();
Klaus Aehlig8cad4bd2016-03-14 11:13:58 +0000116 assertFalse(
117 "Completed action '" + messageFast + "' should not be present in output: " + output,
118 output.contains(messageFast));
119 assertTrue(
120 "Only running action '" + messageSlow + "' should be present in output: " + output,
121 output.contains(messageSlow));
Klaus Aehligc0c88842016-04-11 12:07:38 +0000122
123 terminalWriter = new LoggingTerminalWriter();
124 stateTracker.writeProgressBar(terminalWriter, /* shortVersion=*/ true);
Klaus Aehliged453e02016-04-15 11:29:05 +0000125 output = terminalWriter.getTranscript();
Klaus Aehligc0c88842016-04-11 12:07:38 +0000126 assertFalse(
127 "Completed action '" + messageFast + "' should not be present in short output: " + output,
128 output.contains(messageFast));
129 assertTrue(
130 "Only running action '" + messageSlow + "' should be present in short output: " + output,
131 output.contains(messageSlow));
Klaus Aehlig8cad4bd2016-03-14 11:13:58 +0000132 }
133
134 @Test
135 public void testOldestActionVisible() throws IOException {
Klaus Aehligc0c88842016-04-11 12:07:38 +0000136 // The earliest-started action is always visible somehow in the progress bar
137 // and its short version.
Klaus Aehlig8cad4bd2016-03-14 11:13:58 +0000138
139 String messageOld = "Running the first-started action";
140
Klaus Aehliga63d9612016-04-04 12:15:23 +0000141 ManualClock clock = new ManualClock();
142 clock.advanceMillis(120000);
143 ExperimentalStateTracker stateTracker = new ExperimentalStateTracker(clock);
Klaus Aehlig8cad4bd2016-03-14 11:13:58 +0000144 stateTracker.actionStarted(
145 new ActionStartedEvent(mockAction(messageOld, "bar/foo"), 123456789));
146 for (int i = 0; i < 30; i++) {
147 stateTracker.actionStarted(
148 new ActionStartedEvent(
149 mockAction("Other action " + i, "some/other/actions/number" + i), 123456790 + i));
150 }
151
Klaus Aehliged453e02016-04-15 11:29:05 +0000152 LoggingTerminalWriter terminalWriter = new LoggingTerminalWriter(/*discardHighlight=*/ true);
Klaus Aehlig8cad4bd2016-03-14 11:13:58 +0000153 stateTracker.writeProgressBar(terminalWriter);
Klaus Aehliged453e02016-04-15 11:29:05 +0000154 String output = terminalWriter.getTranscript();
Klaus Aehlig8cad4bd2016-03-14 11:13:58 +0000155 assertTrue(
156 "Longest running action '" + messageOld + "' should be visible in output: " + output,
157 output.contains(messageOld));
Klaus Aehligc0c88842016-04-11 12:07:38 +0000158
Klaus Aehliged453e02016-04-15 11:29:05 +0000159 terminalWriter = new LoggingTerminalWriter(/*discardHighlight=*/ true);
Klaus Aehligc0c88842016-04-11 12:07:38 +0000160 stateTracker.writeProgressBar(terminalWriter, /* shortVersion=*/ true);
Klaus Aehliged453e02016-04-15 11:29:05 +0000161 output = terminalWriter.getTranscript();
Klaus Aehligc0c88842016-04-11 12:07:38 +0000162 assertTrue(
163 "Longest running action '" + messageOld + "' should be visible in short output: " + output,
164 output.contains(messageOld));
Klaus Aehlig8cad4bd2016-03-14 11:13:58 +0000165 }
Klaus Aehlige25642a2016-04-04 13:31:28 +0000166
167 @Test
168 public void testTimesShown() throws IOException {
169 // For sufficiently long running actions, the time that has passed since their start is shown.
Klaus Aehligc0c88842016-04-11 12:07:38 +0000170 // In the short version of the progress bar, this should be true at least for the oldest action.
Klaus Aehlige25642a2016-04-04 13:31:28 +0000171
172 ManualClock clock = new ManualClock();
173 clock.advanceMillis(TimeUnit.SECONDS.toMillis(123));
174 ExperimentalStateTracker stateTracker = new ExperimentalStateTracker(clock);
175 clock.advanceMillis(TimeUnit.SECONDS.toMillis(2));
176
177 stateTracker.actionStarted(
178 new ActionStartedEvent(mockAction("First action", "foo"), clock.nanoTime()));
179 clock.advanceMillis(TimeUnit.SECONDS.toMillis(7));
180 stateTracker.actionStarted(
181 new ActionStartedEvent(mockAction("Second action", "bar"), clock.nanoTime()));
182 clock.advanceMillis(TimeUnit.SECONDS.toMillis(20));
183
Klaus Aehliged453e02016-04-15 11:29:05 +0000184 LoggingTerminalWriter terminalWriter = new LoggingTerminalWriter(/*discardHighlight=*/ true);
Klaus Aehlige25642a2016-04-04 13:31:28 +0000185 stateTracker.writeProgressBar(terminalWriter);
Klaus Aehliged453e02016-04-15 11:29:05 +0000186 String output = terminalWriter.getTranscript();
Klaus Aehlige25642a2016-04-04 13:31:28 +0000187 assertTrue(
188 "Runtime of first action should be visible in output: " + output, output.contains("27s"));
189 assertTrue(
190 "Runtime of second action should be visible in output: " + output, output.contains("20s"));
Klaus Aehligc0c88842016-04-11 12:07:38 +0000191
Klaus Aehliged453e02016-04-15 11:29:05 +0000192 terminalWriter = new LoggingTerminalWriter(/*discardHighlight=*/ true);
Klaus Aehligc0c88842016-04-11 12:07:38 +0000193 stateTracker.writeProgressBar(terminalWriter, /* shortVersion=*/ true);
Klaus Aehliged453e02016-04-15 11:29:05 +0000194 output = terminalWriter.getTranscript();
Klaus Aehligc0c88842016-04-11 12:07:38 +0000195 assertTrue(
196 "Runtime of first action should be visible in short output: " + output,
197 output.contains("27s"));
Klaus Aehlige25642a2016-04-04 13:31:28 +0000198 }
199
Klaus Aehlig2ce24d42016-04-04 15:54:58 +0000200 @Test
201 public void initialProgressBarTimeIndependent() {
202 ManualClock clock = new ManualClock();
203 clock.advanceMillis(TimeUnit.SECONDS.toMillis(123));
204 ExperimentalStateTracker stateTracker = new ExperimentalStateTracker(clock);
205
206 assertFalse(
207 "Initial progress status should be time independent",
208 stateTracker.progressBarTimeDependent());
209 }
210
211 @Test
212 public void runningActionTimeIndependent() {
213 ManualClock clock = new ManualClock();
214 clock.advanceMillis(TimeUnit.SECONDS.toMillis(123));
215 ExperimentalStateTracker stateTracker = new ExperimentalStateTracker(clock);
216 clock.advanceMillis(TimeUnit.SECONDS.toMillis(1));
217 stateTracker.actionStarted(
218 new ActionStartedEvent(mockAction("Some action", "foo"), clock.nanoTime()));
219
220 assertTrue(
221 "Progress bar showing a running action should be time dependent",
222 stateTracker.progressBarTimeDependent());
223 }
Klaus Aehligd232d232016-04-13 09:51:25 +0000224
225 @Test
Klaus Aehligb8d0c6b2016-04-13 11:06:41 +0000226 public void testCountVisible() throws Exception {
Klaus Aehligd232d232016-04-13 09:51:25 +0000227 // The test count should be visible in the status bar, as well as the short status bar
228 ManualClock clock = new ManualClock();
229 ExperimentalStateTracker stateTracker = new ExperimentalStateTracker(clock);
230 TestFilteringCompleteEvent filteringComplete = Mockito.mock(TestFilteringCompleteEvent.class);
Klaus Aehligb8d0c6b2016-04-13 11:06:41 +0000231 Label labelA = Label.parseAbsolute("//foo/bar:baz");
Klaus Aehligd232d232016-04-13 09:51:25 +0000232 ConfiguredTarget targetA = Mockito.mock(ConfiguredTarget.class);
Klaus Aehligb8d0c6b2016-04-13 11:06:41 +0000233 when(targetA.getLabel()).thenReturn(labelA);
Klaus Aehligd232d232016-04-13 09:51:25 +0000234 ConfiguredTarget targetB = Mockito.mock(ConfiguredTarget.class);
235 when(filteringComplete.getTestTargets()).thenReturn(ImmutableSet.of(targetA, targetB));
236 TestSummary testSummary = Mockito.mock(TestSummary.class);
Klaus Aehligb8d0c6b2016-04-13 11:06:41 +0000237 when(testSummary.getTarget()).thenReturn(targetA);
238
Klaus Aehligd232d232016-04-13 09:51:25 +0000239 stateTracker.testFilteringComplete(filteringComplete);
240 stateTracker.testSummary(testSummary);
241
Klaus Aehliged453e02016-04-15 11:29:05 +0000242 LoggingTerminalWriter terminalWriter = new LoggingTerminalWriter(/*discardHighlight=*/ true);
Klaus Aehligd232d232016-04-13 09:51:25 +0000243 stateTracker.writeProgressBar(terminalWriter);
Klaus Aehliged453e02016-04-15 11:29:05 +0000244 String output = terminalWriter.getTranscript();
Klaus Aehligd232d232016-04-13 09:51:25 +0000245 assertTrue(
246 "Test count should be visible in output: " + output, output.contains(" 1 / 2 tests"));
247
Klaus Aehliged453e02016-04-15 11:29:05 +0000248 terminalWriter = new LoggingTerminalWriter(/*discardHighlight=*/ true);
Klaus Aehligd232d232016-04-13 09:51:25 +0000249 stateTracker.writeProgressBar(terminalWriter, /* shortVersion=*/ true);
Klaus Aehliged453e02016-04-15 11:29:05 +0000250 output = terminalWriter.getTranscript();
Klaus Aehligd232d232016-04-13 09:51:25 +0000251 assertTrue(
252 "Test count should be visible in short output: " + output, output.contains(" 1 / 2 tests"));
253 }
Klaus Aehligb8d0c6b2016-04-13 11:06:41 +0000254
255 @Test
256 public void testPassedVisible() throws Exception {
257 // The last test that passed should still be visible in the long status bar.
258 ManualClock clock = new ManualClock();
259 ExperimentalStateTracker stateTracker = new ExperimentalStateTracker(clock);
260 TestFilteringCompleteEvent filteringComplete = Mockito.mock(TestFilteringCompleteEvent.class);
261 Label labelA = Label.parseAbsolute("//foo/bar:baz");
262 ConfiguredTarget targetA = Mockito.mock(ConfiguredTarget.class);
263 when(targetA.getLabel()).thenReturn(labelA);
264 ConfiguredTarget targetB = Mockito.mock(ConfiguredTarget.class);
265 when(filteringComplete.getTestTargets()).thenReturn(ImmutableSet.of(targetA, targetB));
266 TestSummary testSummary = Mockito.mock(TestSummary.class);
267 when(testSummary.getStatus()).thenReturn(BlazeTestStatus.PASSED);
268 when(testSummary.getTarget()).thenReturn(targetA);
269
270 stateTracker.testFilteringComplete(filteringComplete);
271 stateTracker.testSummary(testSummary);
272
Klaus Aehliged453e02016-04-15 11:29:05 +0000273 LoggingTerminalWriter terminalWriter = new LoggingTerminalWriter(/*discardHighlight=*/ true);
Klaus Aehligb8d0c6b2016-04-13 11:06:41 +0000274 stateTracker.writeProgressBar(terminalWriter);
Klaus Aehliged453e02016-04-15 11:29:05 +0000275 String output = terminalWriter.getTranscript();
Klaus Aehligb8d0c6b2016-04-13 11:06:41 +0000276
277 assertTrue(
278 "Label " + labelA.toString() + " should be present in progress bar: " + output,
279 output.contains(labelA.toString()));
280 }
Klaus Aehlig6d0876a2016-04-15 14:41:07 +0000281
282 private void doTestOutputLength(boolean withTest, int actions) throws Exception {
283 // If we target 70 characters, then there should be enough space to both,
284 // keep the line limit, and show the local part of the running actions and
285 // the passed test.
286 ManualClock clock = new ManualClock();
287 ExperimentalStateTracker stateTracker = new ExperimentalStateTracker(clock, 70);
288
289 Action foobuildAction = mockAction(
290 "Building //src/some/very/long/path/long/long/long/long/long/long/long/foo/foobuild.jar",
291 "//src/some/very/long/path/long/long/long/long/long/long/long/foo:foobuild");
292 Action bazbuildAction = mockAction(
293 "Building //src/some/very/long/path/long/long/long/long/long/long/long/baz/bazbuild.jar",
294 "//src/some/very/long/path/long/long/long/long/long/long/long/baz:bazbuild");
295
296 Label bartestLabel = Label.parseAbsolute(
297 "//src/another/very/long/long/path/long/long/long/long/long/long/long/long/bars:bartest");
298 ConfiguredTarget bartestTarget = Mockito.mock(ConfiguredTarget.class);
299 when(bartestTarget.getLabel()).thenReturn(bartestLabel);
300
301 TestFilteringCompleteEvent filteringComplete = Mockito.mock(TestFilteringCompleteEvent.class);
302 when(filteringComplete.getTestTargets()).thenReturn(ImmutableSet.of(bartestTarget));
303
304 TestSummary testSummary = Mockito.mock(TestSummary.class);
305 when(testSummary.getStatus()).thenReturn(BlazeTestStatus.PASSED);
306 when(testSummary.getTarget()).thenReturn(bartestTarget);
307
308 if (actions >= 1) {
309 stateTracker.actionStarted(new ActionStartedEvent(foobuildAction, 123456789));
310 }
311 if (actions >= 2) {
312 stateTracker.actionStarted(new ActionStartedEvent(bazbuildAction, 123456900));
313 }
314 if (withTest) {
315 stateTracker.testFilteringComplete(filteringComplete);
316 stateTracker.testSummary(testSummary);
317 }
318
319 LoggingTerminalWriter terminalWriter = new LoggingTerminalWriter(/*discardHighlight=*/ true);
320 stateTracker.writeProgressBar(terminalWriter);
321 String output = terminalWriter.getTranscript();
322
323 assertTrue(
324 "Only lines with at most 70 chars should be present in the output:\n" + output,
325 longestLine(output) <= 70);
326 if (actions >= 1) {
327 assertTrue(
328 "Running action 'foobuild' should be mentioned in output:\n" + output,
329 output.contains("foobuild"));
330 }
331 if (actions >= 2) {
332 assertTrue(
333 "Running action 'bazbuild' should be mentioned in output:\n" + output,
334 output.contains("bazbuild"));
335 }
336 if (withTest) {
337 assertTrue(
338 "Passed test ':bartest' should be mentioned in output:\n" + output,
339 output.contains(":bartest"));
340 }
341 }
342
343 @Test
344 public void testOutputLength() throws Exception {
345 for (int i = 0; i < 3; i++) {
346 doTestOutputLength(true, i);
347 doTestOutputLength(false, i);
348 }
349 }
Klaus Aehlig8cad4bd2016-03-14 11:13:58 +0000350}