1 /*
2 * Copyright 2022 Google LLC
3 *
4 * Licensed under the Apache License, Version 2.0 (the "License");
5 * you may not use this file except in compliance with the License.
6 * You may obtain a copy of the License at
7 *
8 * http://www.apache.org/licenses/LICENSE-2.0
9 *
10 * Unless required by applicable law or agreed to in writing, software
11 * distributed under the License is distributed on an "AS IS" BASIS,
12 * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
13 * See the License for the specific language governing permissions and
14 * limitations under the License.
15 */
16
17 #include "fcp/base/wall_clock_stopwatch.h"
18
19 #include <memory>
20
21 #include "gmock/gmock.h"
22 #include "gtest/gtest.h"
23 #include "absl/time/time.h"
24 #include "fcp/base/clock.h"
25 #include "fcp/base/scheduler.h"
26
27 namespace fcp {
28
29 using ::testing::AllOf;
30 using ::testing::Eq;
31 using ::testing::Ge;
32 using ::testing::Lt;
33
TEST(WallClockStopwatchTest,NoopHandle)34 TEST(WallClockStopwatchTest, NoopHandle) {
35 // These noop handles should not crash (or do anything).
36 auto stopwatch = WallClockStopwatch::CreateNoop();
37 {
38 auto started_stopwatch1 = stopwatch->Start();
39 auto started_stopwatch2 = stopwatch->Start();
40 }
41 EXPECT_THAT(stopwatch->GetTotalDuration(), Eq(absl::ZeroDuration()));
42 }
43
TEST(WallClockStopwatchTest,ShouldBeInitializedToZero)44 TEST(WallClockStopwatchTest, ShouldBeInitializedToZero) {
45 auto stopwatch = WallClockStopwatch::Create();
46 EXPECT_THAT(stopwatch->GetTotalDuration(), Eq(absl::ZeroDuration()));
47 }
48
TEST(WallClockStopwatchTest,SingleThreadSingleStart)49 TEST(WallClockStopwatchTest, SingleThreadSingleStart) {
50 auto stopwatch = WallClockStopwatch::Create();
51
52 {
53 auto started_stopwatch = stopwatch->Start();
54 absl::SleepFor(absl::Milliseconds(100));
55 }
56
57 EXPECT_THAT(stopwatch->GetTotalDuration(), Ge(absl::Milliseconds(100)));
58 }
59
TEST(WallClockStopwatchTest,SingleThreadMultipleSequentialStartStop)60 TEST(WallClockStopwatchTest, SingleThreadMultipleSequentialStartStop) {
61 auto stopwatch = WallClockStopwatch::Create();
62
63 {
64 auto started_stopwatch = stopwatch->Start();
65 absl::SleepFor(absl::Milliseconds(100));
66 }
67
68 EXPECT_THAT(stopwatch->GetTotalDuration(), Ge(absl::Milliseconds(100)));
69
70 absl::SleepFor(absl::Milliseconds(100));
71 // The SleepFor should not be reflect in the measurement, since the stopwatch
72 // was stopped.
73 EXPECT_THAT(stopwatch->GetTotalDuration(), Ge(absl::Milliseconds(100)));
74
75 {
76 auto started_stopwatch = stopwatch->Start();
77 absl::SleepFor(absl::Milliseconds(100));
78 }
79 EXPECT_THAT(stopwatch->GetTotalDuration(), Ge(absl::Milliseconds(200)));
80 }
81
TEST(WallClockStopwatchTest,ShouldReflectOngoingMeasurement)82 TEST(WallClockStopwatchTest, ShouldReflectOngoingMeasurement) {
83 auto stopwatch = WallClockStopwatch::Create();
84
85 {
86 auto started_stopwatch = stopwatch->Start();
87 absl::SleepFor(absl::Milliseconds(100));
88 EXPECT_THAT(stopwatch->GetTotalDuration(), Ge(absl::Milliseconds(100)));
89 absl::SleepFor(absl::Milliseconds(100));
90 }
91
92 EXPECT_THAT(stopwatch->GetTotalDuration(), Ge(absl::Milliseconds(200)));
93 }
94
TEST(WallClockStopwatchTest,SingleThreadMultipleConcurrentStart)95 TEST(WallClockStopwatchTest, SingleThreadMultipleConcurrentStart) {
96 auto stopwatch = WallClockStopwatch::Create();
97
98 {
99 auto started_stopwatch1 = stopwatch->Start();
100 absl::SleepFor(absl::Milliseconds(100));
101 EXPECT_THAT(stopwatch->GetTotalDuration(), Ge(absl::Milliseconds(100)));
102 {
103 auto started_stopwatch2 = stopwatch->Start();
104 absl::SleepFor(absl::Milliseconds(100));
105 EXPECT_THAT(stopwatch->GetTotalDuration(), Ge(absl::Milliseconds(200)));
106 {
107 auto started_stopwatch3 = stopwatch->Start();
108 absl::SleepFor(absl::Milliseconds(100));
109 }
110 }
111 }
112 EXPECT_THAT(stopwatch->GetTotalDuration(), Ge(absl::Milliseconds(300)));
113 }
114
115 /** Tests that the stopwatch truly measures wall clock time, and not the
116 * cumulative (but concurrent) time spent in each separate thread. */
TEST(WallClockStopwatchTest,ThreeThreadsThreeTasks)117 TEST(WallClockStopwatchTest, ThreeThreadsThreeTasks) {
118 auto stopwatch = WallClockStopwatch::Create();
119 std::unique_ptr<Scheduler> scheduler =
120 CreateThreadPoolScheduler(/*thread_count=*/3);
121
122 scheduler->Schedule([&stopwatch]() {
123 auto started_stopwatch = stopwatch->Start();
124 absl::SleepFor(absl::Milliseconds(100));
125 EXPECT_THAT(stopwatch->GetTotalDuration(), Ge(absl::Milliseconds(100)));
126 });
127 scheduler->Schedule([&stopwatch]() {
128 auto started_stopwatch = stopwatch->Start();
129 absl::SleepFor(absl::Milliseconds(100));
130 EXPECT_THAT(stopwatch->GetTotalDuration(), Ge(absl::Milliseconds(100)));
131 });
132 scheduler->Schedule([&stopwatch]() {
133 auto started_stopwatch = stopwatch->Start();
134 absl::SleepFor(absl::Milliseconds(100));
135 EXPECT_THAT(stopwatch->GetTotalDuration(), Ge(absl::Milliseconds(100)));
136 });
137 scheduler->WaitUntilIdle();
138 // The stopwatch should only have measured ~100ms of wall clock time, since
139 // the three threads will have run concurrently (we use a margin of 50 extra
140 // ms since these can be quite slow when run with ASAN/TSAN).
141 EXPECT_THAT(stopwatch->GetTotalDuration(),
142 AllOf(Ge(absl::Milliseconds(100)), Lt(absl::Milliseconds(150))));
143 }
144
145 /** Tests that the stopwatch truly measures wall clock time, but this time in a
146 * scenario where there are only 2 threads so the third measurement *will*
147 * happen sequentially. */
TEST(WallClockStopwatchTest,TwoThreadsThreeTasks)148 TEST(WallClockStopwatchTest, TwoThreadsThreeTasks) {
149 auto stopwatch = WallClockStopwatch::Create();
150 std::unique_ptr<Scheduler> scheduler =
151 CreateThreadPoolScheduler(/*thread_count=*/2);
152
153 scheduler->Schedule([&stopwatch]() {
154 auto started_stopwatch = stopwatch->Start();
155 absl::SleepFor(absl::Milliseconds(100));
156 EXPECT_THAT(stopwatch->GetTotalDuration(), Ge(absl::Milliseconds(100)));
157 });
158 scheduler->Schedule([&stopwatch]() {
159 auto started_stopwatch = stopwatch->Start();
160 absl::SleepFor(absl::Milliseconds(100));
161 EXPECT_THAT(stopwatch->GetTotalDuration(), Ge(absl::Milliseconds(100)));
162 });
163 scheduler->Schedule([&stopwatch]() {
164 auto started_stopwatch = stopwatch->Start();
165 absl::SleepFor(absl::Milliseconds(100));
166 EXPECT_THAT(stopwatch->GetTotalDuration(), Ge(absl::Milliseconds(200)));
167 });
168 scheduler->WaitUntilIdle();
169 // The stopwatch should have measured ~200ms of wall clock time, since the
170 // two threads will have run concurrently but there were three tasks, so the
171 // third task will have run sequentially.
172 EXPECT_THAT(stopwatch->GetTotalDuration(),
173 AllOf(Ge(absl::Milliseconds(200)), Lt(absl::Milliseconds(250))));
174 }
175
176 /** Tests that the stopwatch handles stop/starts across different threads
177 * correctly, including partially overlapping measurements. */
TEST(WallClockStopwatchTest,TwoThreadsMultipleOverlappingStartStop)178 TEST(WallClockStopwatchTest, TwoThreadsMultipleOverlappingStartStop) {
179 auto stopwatch = WallClockStopwatch::Create();
180 std::unique_ptr<Scheduler> scheduler =
181 CreateThreadPoolScheduler(/*thread_count=*/2);
182
183 scheduler->Schedule([&stopwatch]() {
184 auto started_stopwatch = stopwatch->Start();
185 absl::SleepFor(absl::Milliseconds(100));
186 EXPECT_THAT(stopwatch->GetTotalDuration(), Ge(absl::Milliseconds(100)));
187 });
188 scheduler->Schedule([&stopwatch]() {
189 auto started_stopwatch = stopwatch->Start();
190 absl::SleepFor(absl::Milliseconds(50));
191 EXPECT_THAT(stopwatch->GetTotalDuration(), Ge(absl::Milliseconds(50)));
192 });
193 scheduler->Schedule([&stopwatch]() {
194 auto started_stopwatch = stopwatch->Start();
195 absl::SleepFor(absl::Milliseconds(50));
196 EXPECT_THAT(stopwatch->GetTotalDuration(), Ge(absl::Milliseconds(100)));
197 });
198 scheduler->WaitUntilIdle();
199
200 // The stopwatch should have measured ~100ms of wall clock time until now,
201 // since the two threads will have run concurrently and there were three
202 // tasks, which should all have been able to run concurrently within that
203 // time.
204 EXPECT_THAT(stopwatch->GetTotalDuration(),
205 AllOf(Ge(absl::Milliseconds(100)), Lt(absl::Milliseconds(150))));
206
207 absl::SleepFor(absl::Milliseconds(100));
208 // The SleepFor should not be reflected in the measurement since all
209 // stopwatches were stopped.
210 EXPECT_THAT(stopwatch->GetTotalDuration(),
211 AllOf(Ge(absl::Milliseconds(100)), Lt(absl::Milliseconds(150))));
212
213 {
214 auto outer_started_stopwatch = stopwatch->Start();
215 absl::SleepFor(absl::Milliseconds(50));
216 EXPECT_THAT(stopwatch->GetTotalDuration(), Ge(absl::Milliseconds(150)));
217 scheduler->Schedule([&stopwatch]() {
218 auto started_stopwatch = stopwatch->Start();
219 absl::SleepFor(absl::Milliseconds(200));
220 EXPECT_THAT(stopwatch->GetTotalDuration(), Ge(absl::Milliseconds(350)));
221 });
222 scheduler->Schedule([&stopwatch]() {
223 auto started_stopwatch = stopwatch->Start();
224 absl::SleepFor(absl::Milliseconds(50));
225 EXPECT_THAT(stopwatch->GetTotalDuration(), Ge(absl::Milliseconds(200)));
226 });
227 scheduler->Schedule([&stopwatch]() {
228 auto started_stopwatch = stopwatch->Start();
229 absl::SleepFor(absl::Milliseconds(350));
230 EXPECT_THAT(stopwatch->GetTotalDuration(), Ge(absl::Milliseconds(500)));
231 });
232 scheduler->WaitUntilIdle();
233
234 // The stopwatch should have measured ~550ms of wall clock time until now:
235 // the previous ~100ms measurement + 50ms + 50ms + 350ms (the shortest
236 // critical path for the above three tasks).
237 //
238 // Note that the outer stopwatch is still active so the measurement is still
239 // ongoing.
240 EXPECT_THAT(
241 stopwatch->GetTotalDuration(),
242 AllOf(Ge(absl::Milliseconds(550)), Lt(absl::Milliseconds(600))));
243 absl::SleepFor(absl::Milliseconds(100));
244 }
245
246 // The final SleepFor should now also be reflected.
247 EXPECT_THAT(stopwatch->GetTotalDuration(),
248 AllOf(Ge(absl::Milliseconds(650)), Lt(absl::Milliseconds(700))));
249 }
250
251 } // namespace fcp
252