1 // Copyright 2017 The Chromium Authors
2 // Use of this source code is governed by a BSD-style license that can be
3 // found in the LICENSE file.
4
5 #ifdef UNSAFE_BUFFERS_BUILD
6 // TODO(crbug.com/40284755): Remove this and spanify to fix the errors.
7 #pragma allow_unsafe_buffers
8 #endif
9
10 #include "base/threading/scoped_blocking_call.h"
11
12 #include <memory>
13 #include <optional>
14 #include <utility>
15 #include <vector>
16
17 #include "base/barrier_closure.h"
18 #include "base/functional/bind.h"
19 #include "base/functional/callback.h"
20 #include "base/task/thread_pool.h"
21 #include "base/task/thread_pool/environment_config.h"
22 #include "base/task/thread_pool/thread_pool_impl.h"
23 #include "base/test/bind.h"
24 #include "base/test/gtest_util.h"
25 #include "base/test/task_environment.h"
26 #include "base/test/test_waitable_event.h"
27 #include "base/threading/scoped_blocking_call_internal.h"
28 #include "base/threading/thread_restrictions.h"
29 #include "base/time/time_override.h"
30 #include "build/build_config.h"
31 #include "testing/gmock/include/gmock/gmock.h"
32 #include "testing/gtest/include/gtest/gtest.h"
33
34 using testing::ElementsAre;
35
36 namespace base {
37
38 namespace {
39
40 class MockBlockingObserver : public internal::BlockingObserver {
41 public:
42 MockBlockingObserver() = default;
43
44 MockBlockingObserver(const MockBlockingObserver&) = delete;
45 MockBlockingObserver& operator=(const MockBlockingObserver&) = delete;
46
47 MOCK_METHOD1(BlockingStarted, void(BlockingType));
48 MOCK_METHOD0(BlockingTypeUpgraded, void());
49 MOCK_METHOD0(BlockingEnded, void());
50 };
51
52 class ScopedBlockingCallTest : public testing::Test {
53 public:
54 ScopedBlockingCallTest(const ScopedBlockingCallTest&) = delete;
55 ScopedBlockingCallTest& operator=(const ScopedBlockingCallTest&) = delete;
56
57 protected:
ScopedBlockingCallTest()58 ScopedBlockingCallTest() {
59 internal::SetBlockingObserverForCurrentThread(&observer_);
60 }
61
~ScopedBlockingCallTest()62 ~ScopedBlockingCallTest() override {
63 internal::ClearBlockingObserverForCurrentThread();
64 }
65
66 testing::StrictMock<MockBlockingObserver> observer_;
67 };
68
69 } // namespace
70
TEST_F(ScopedBlockingCallTest,MayBlock)71 TEST_F(ScopedBlockingCallTest, MayBlock) {
72 EXPECT_CALL(observer_, BlockingStarted(BlockingType::MAY_BLOCK));
73 ScopedBlockingCall scoped_blocking_call(FROM_HERE, BlockingType::MAY_BLOCK);
74 testing::Mock::VerifyAndClear(&observer_);
75 EXPECT_CALL(observer_, BlockingEnded());
76 }
77
TEST_F(ScopedBlockingCallTest,WillBlock)78 TEST_F(ScopedBlockingCallTest, WillBlock) {
79 EXPECT_CALL(observer_, BlockingStarted(BlockingType::WILL_BLOCK));
80 ScopedBlockingCall scoped_blocking_call(FROM_HERE, BlockingType::WILL_BLOCK);
81 testing::Mock::VerifyAndClear(&observer_);
82 EXPECT_CALL(observer_, BlockingEnded());
83 }
84
TEST_F(ScopedBlockingCallTest,MayBlockWillBlock)85 TEST_F(ScopedBlockingCallTest, MayBlockWillBlock) {
86 EXPECT_CALL(observer_, BlockingStarted(BlockingType::MAY_BLOCK));
87 ScopedBlockingCall scoped_blocking_call_a(FROM_HERE, BlockingType::MAY_BLOCK);
88 testing::Mock::VerifyAndClear(&observer_);
89
90 {
91 EXPECT_CALL(observer_, BlockingTypeUpgraded());
92 ScopedBlockingCall scoped_blocking_call_b(FROM_HERE,
93 BlockingType::WILL_BLOCK);
94 testing::Mock::VerifyAndClear(&observer_);
95 }
96
97 EXPECT_CALL(observer_, BlockingEnded());
98 }
99
TEST_F(ScopedBlockingCallTest,WillBlockMayBlock)100 TEST_F(ScopedBlockingCallTest, WillBlockMayBlock) {
101 EXPECT_CALL(observer_, BlockingStarted(BlockingType::WILL_BLOCK));
102 ScopedBlockingCall scoped_blocking_call_a(FROM_HERE,
103 BlockingType::WILL_BLOCK);
104 testing::Mock::VerifyAndClear(&observer_);
105
106 {
107 ScopedBlockingCall scoped_blocking_call_b(FROM_HERE,
108 BlockingType::MAY_BLOCK);
109 }
110
111 EXPECT_CALL(observer_, BlockingEnded());
112 }
113
TEST_F(ScopedBlockingCallTest,MayBlockMayBlock)114 TEST_F(ScopedBlockingCallTest, MayBlockMayBlock) {
115 EXPECT_CALL(observer_, BlockingStarted(BlockingType::MAY_BLOCK));
116 ScopedBlockingCall scoped_blocking_call_a(FROM_HERE, BlockingType::MAY_BLOCK);
117 testing::Mock::VerifyAndClear(&observer_);
118
119 {
120 ScopedBlockingCall scoped_blocking_call_b(FROM_HERE,
121 BlockingType::MAY_BLOCK);
122 }
123
124 EXPECT_CALL(observer_, BlockingEnded());
125 }
126
TEST_F(ScopedBlockingCallTest,WillBlockWillBlock)127 TEST_F(ScopedBlockingCallTest, WillBlockWillBlock) {
128 EXPECT_CALL(observer_, BlockingStarted(BlockingType::WILL_BLOCK));
129 ScopedBlockingCall scoped_blocking_call_a(FROM_HERE,
130 BlockingType::WILL_BLOCK);
131 testing::Mock::VerifyAndClear(&observer_);
132
133 {
134 ScopedBlockingCall scoped_blocking_call_b(FROM_HERE,
135 BlockingType::WILL_BLOCK);
136 }
137
138 EXPECT_CALL(observer_, BlockingEnded());
139 }
140
TEST_F(ScopedBlockingCallTest,MayBlockWillBlockTwice)141 TEST_F(ScopedBlockingCallTest, MayBlockWillBlockTwice) {
142 EXPECT_CALL(observer_, BlockingStarted(BlockingType::MAY_BLOCK));
143 ScopedBlockingCall scoped_blocking_call_a(FROM_HERE, BlockingType::MAY_BLOCK);
144 testing::Mock::VerifyAndClear(&observer_);
145
146 {
147 EXPECT_CALL(observer_, BlockingTypeUpgraded());
148 ScopedBlockingCall scoped_blocking_call_b(FROM_HERE,
149 BlockingType::WILL_BLOCK);
150 testing::Mock::VerifyAndClear(&observer_);
151
152 {
153 ScopedBlockingCall scoped_blocking_call_c(FROM_HERE,
154 BlockingType::MAY_BLOCK);
155 ScopedBlockingCall scoped_blocking_call_d(FROM_HERE,
156 BlockingType::WILL_BLOCK);
157 }
158 }
159
160 EXPECT_CALL(observer_, BlockingEnded());
161 }
162
TEST(ScopedBlockingCallDestructionOrderTest,InvalidDestructionOrder)163 TEST(ScopedBlockingCallDestructionOrderTest, InvalidDestructionOrder) {
164 auto scoped_blocking_call_a =
165 std::make_unique<ScopedBlockingCall>(FROM_HERE, BlockingType::WILL_BLOCK);
166 auto scoped_blocking_call_b =
167 std::make_unique<ScopedBlockingCall>(FROM_HERE, BlockingType::WILL_BLOCK);
168
169 EXPECT_DCHECK_DEATH({ scoped_blocking_call_a.reset(); });
170 }
171
172 namespace {
173
174 class ScopedBlockingCallIOJankMonitoringTest : public testing::Test {
175 public:
ScopedBlockingCallIOJankMonitoringTest(test::TaskEnvironment::TimeSource time_source=test::TaskEnvironment::TimeSource::MOCK_TIME)176 explicit ScopedBlockingCallIOJankMonitoringTest(
177 test::TaskEnvironment::TimeSource time_source =
178 test::TaskEnvironment::TimeSource::MOCK_TIME)
179 : task_environment_(std::in_place, time_source) {}
180
SetUp()181 void SetUp() override {
182 // Note 1: While EnableIOJankMonitoringForProcess() is documented as being
183 // only callable once per process. The call to CancelMonitoringForTesting()
184 // in TearDown() makes it okay to call this in multiple tests in a row
185 // within a single process.
186 // Note 2: No need to check TimeTicks::IsConsistentAcrossProcesses() in
187 // spite of EnableIOJankMonitoringForProcess()'s requirement as
188 // TimeSource::MOCK_TIME avoids usage of the system clock and avoids the
189 // issue.
190 // OnlyObservedThreadsForTest(true) to prevent flakes which are believed to
191 // be caused by ScopedBlockingCall interference in the same process but
192 // outside this test's managed threads: crbug.com/1071166.
193 EnableIOJankMonitoringForProcess(
194 BindLambdaForTesting([&](int janky_intervals_per_minute,
195 int total_janks_per_minute) {
196 reports_.emplace_back(
197 janky_intervals_per_minute, total_janks_per_minute);
198 }),
199 OnlyObservedThreadsForTest(true));
200
201 internal::SetBlockingObserverForCurrentThread(&main_thread_observer);
202 }
203
StopMonitoring()204 void StopMonitoring() {
205 // Reclaim worker threads before CancelMonitoringForTesting() to avoid a
206 // data race (crbug.com/1071166#c16).
207 task_environment_.reset();
208 internal::IOJankMonitoringWindow::CancelMonitoringForTesting();
209 internal::ClearBlockingObserverForCurrentThread();
210 }
211
TearDown()212 void TearDown() override {
213 if (task_environment_)
214 StopMonitoring();
215 }
216
217 protected:
218 // A member initialized before |task_environment_| that forces worker threads
219 // to be started synchronously. This avoids a tricky race where Linux invokes
220 // SetCurrentThreadType() from early main, before invoking ThreadMain and
221 // yielding control to the thread pool impl. That causes a ScopedBlockingCall
222 // in platform_thread_linux.cc:SetThreadCgroupForThreadType and interferes
223 // with this test. This solution is quite intrusive but is the simplest we can
224 // do for this unique corner case.
225 struct SetSynchronousThreadStart {
SetSynchronousThreadStartbase::__anon86d6840e0211::ScopedBlockingCallIOJankMonitoringTest::SetSynchronousThreadStart226 SetSynchronousThreadStart() {
227 internal::ThreadPoolImpl::SetSynchronousThreadStartForTesting(true);
228 }
~SetSynchronousThreadStartbase::__anon86d6840e0211::ScopedBlockingCallIOJankMonitoringTest::SetSynchronousThreadStart229 ~SetSynchronousThreadStart() {
230 internal::ThreadPoolImpl::SetSynchronousThreadStartForTesting(false);
231 }
232 } set_synchronous_thread_start_;
233
234 // The registered lambda above may report to this from any thread. It is
235 // nonetheless safe to read this from the test body as
236 // TaskEnvironment+MOCK_TIME advances the test in lock steps.
237 std::vector<std::pair<int, int>> reports_;
238
239 std::optional<test::TaskEnvironment> task_environment_;
240
241 // The main thread needs to register a BlockingObserver per
242 // OnlyObservedThreadsForTest(true) but doesn't otherwise care about
243 // observing.
244 testing::NiceMock<MockBlockingObserver> main_thread_observer;
245 };
246
247 } // namespace
248
TEST_F(ScopedBlockingCallIOJankMonitoringTest,Basic)249 TEST_F(ScopedBlockingCallIOJankMonitoringTest, Basic) {
250 constexpr auto kJankTiming =
251 internal::IOJankMonitoringWindow::kIOJankInterval * 7;
252 {
253 ScopedBlockingCall blocked_for_7s(FROM_HERE, BlockingType::MAY_BLOCK);
254 task_environment_->FastForwardBy(kJankTiming);
255 }
256
257 // No janks reported before the monitoring window completes.
258 EXPECT_THAT(reports_, ElementsAre());
259
260 // Advance precisely to the end of this window.
261 task_environment_->FastForwardBy(
262 internal::IOJankMonitoringWindow::kMonitoringWindow - kJankTiming);
263
264 EXPECT_THAT(reports_, ElementsAre(std::make_pair(7, 7)));
265 }
266
TEST_F(ScopedBlockingCallIOJankMonitoringTest,NestedDoesntMatter)267 TEST_F(ScopedBlockingCallIOJankMonitoringTest, NestedDoesntMatter) {
268 constexpr auto kJankTiming =
269 internal::IOJankMonitoringWindow::kIOJankInterval * 7;
270 {
271 ScopedBlockingCall blocked_for_7s(FROM_HERE, BlockingType::MAY_BLOCK);
272 ScopedBlockingCall nested(FROM_HERE, BlockingType::MAY_BLOCK);
273 task_environment_->FastForwardBy(kJankTiming);
274 }
275
276 // No janks reported before the monitoring window completes.
277 EXPECT_THAT(reports_, ElementsAre());
278
279 // Jump to the next window.
280 task_environment_->FastForwardBy(
281 internal::IOJankMonitoringWindow::kMonitoringWindow);
282
283 EXPECT_THAT(reports_, ElementsAre(std::make_pair(7, 7)));
284 }
285
TEST_F(ScopedBlockingCallIOJankMonitoringTest,ManyInAWindow)286 TEST_F(ScopedBlockingCallIOJankMonitoringTest, ManyInAWindow) {
287 constexpr auto kJankTiming =
288 internal::IOJankMonitoringWindow::kIOJankInterval * 7;
289 constexpr auto kIdleTiming = Seconds(3);
290
291 for (int i = 0; i < 3; ++i) {
292 {
293 ScopedBlockingCall blocked_for_7s(FROM_HERE, BlockingType::MAY_BLOCK);
294 task_environment_->FastForwardBy(kJankTiming);
295 }
296 task_environment_->FastForwardBy(kIdleTiming);
297 }
298
299 // No janks reported before the monitoring window completes.
300 EXPECT_THAT(reports_, ElementsAre());
301
302 // Complete the current window.
303 task_environment_->FastForwardBy(
304 internal::IOJankMonitoringWindow::kMonitoringWindow -
305 (kJankTiming + kIdleTiming) * 3);
306
307 EXPECT_THAT(reports_, ElementsAre(std::make_pair(7 * 3, 7 * 3)));
308 }
309
TEST_F(ScopedBlockingCallIOJankMonitoringTest,OverlappingMultipleWindows)310 TEST_F(ScopedBlockingCallIOJankMonitoringTest, OverlappingMultipleWindows) {
311 constexpr auto kJankTiming =
312 internal::IOJankMonitoringWindow::kMonitoringWindow * 3 +
313 internal::IOJankMonitoringWindow::kIOJankInterval * 5;
314
315 {
316 ScopedBlockingCall blocked_for_3windows(FROM_HERE, BlockingType::MAY_BLOCK);
317 task_environment_->FastForwardBy(kJankTiming);
318 }
319
320 // Fast-forward by another window with no active blocking calls.
321 task_environment_->FastForwardBy(
322 internal::IOJankMonitoringWindow::kMonitoringWindow);
323
324 // 3 windows janky for their full breadth and 1 window janky for 5 seconds.
325 EXPECT_THAT(reports_,
326 ElementsAre(std::make_pair(60, 60), std::make_pair(60, 60),
327 std::make_pair(60, 60), std::make_pair(5, 5)));
328 }
329
TEST_F(ScopedBlockingCallIOJankMonitoringTest,InstantUnblockReportsZero)330 TEST_F(ScopedBlockingCallIOJankMonitoringTest, InstantUnblockReportsZero) {
331 { ScopedBlockingCall instant_unblock(FROM_HERE, BlockingType::MAY_BLOCK); }
332
333 // No janks reported before the monitoring window completes.
334 EXPECT_THAT(reports_, ElementsAre());
335
336 task_environment_->FastForwardBy(
337 internal::IOJankMonitoringWindow::kMonitoringWindow);
338
339 EXPECT_THAT(reports_, ElementsAre(std::make_pair(0, 0)));
340
341 // No blocking call in next window also reports zero.
342 task_environment_->FastForwardBy(
343 internal::IOJankMonitoringWindow::kMonitoringWindow);
344 EXPECT_THAT(reports_,
345 ElementsAre(std::make_pair(0, 0), std::make_pair(0, 0)));
346 }
347
348 // Start the jank mid-interval; that interval should be counted but the last
349 // incomplete interval won't count.
TEST_F(ScopedBlockingCallIOJankMonitoringTest,Jank7sMidInterval)350 TEST_F(ScopedBlockingCallIOJankMonitoringTest, Jank7sMidInterval) {
351 task_environment_->FastForwardBy(
352 internal::IOJankMonitoringWindow::kIOJankInterval / 3);
353
354 constexpr auto kJankTiming =
355 internal::IOJankMonitoringWindow::kIOJankInterval * 7;
356 {
357 ScopedBlockingCall blocked_for_7s(FROM_HERE, BlockingType::MAY_BLOCK);
358 task_environment_->FastForwardBy(kJankTiming);
359 }
360
361 // No janks reported before the monitoring window completes.
362 EXPECT_THAT(reports_, ElementsAre());
363
364 task_environment_->FastForwardBy(
365 internal::IOJankMonitoringWindow::kMonitoringWindow);
366
367 EXPECT_THAT(reports_, ElementsAre(std::make_pair(7, 7)));
368 }
369
370 // Start the jank mid-interval; that interval should be counted but the second
371 // one won't count.
TEST_F(ScopedBlockingCallIOJankMonitoringTest,Jank1sMidInterval)372 TEST_F(ScopedBlockingCallIOJankMonitoringTest, Jank1sMidInterval) {
373 task_environment_->FastForwardBy(
374 internal::IOJankMonitoringWindow::kIOJankInterval / 3);
375
376 constexpr auto kJankTiming =
377 internal::IOJankMonitoringWindow::kIOJankInterval;
378 {
379 ScopedBlockingCall blocked_for_1s(FROM_HERE, BlockingType::MAY_BLOCK);
380 task_environment_->FastForwardBy(kJankTiming);
381 }
382
383 // No janks reported before the monitoring window completes.
384 EXPECT_THAT(reports_, ElementsAre());
385
386 task_environment_->FastForwardBy(
387 internal::IOJankMonitoringWindow::kMonitoringWindow);
388
389 EXPECT_THAT(reports_, ElementsAre(std::make_pair(1, 1)));
390 }
391
392 // Jank that lasts for 1.3 intervals should be rounded down to 1.
TEST_F(ScopedBlockingCallIOJankMonitoringTest,JankRoundDown)393 TEST_F(ScopedBlockingCallIOJankMonitoringTest, JankRoundDown) {
394 task_environment_->FastForwardBy(
395 internal::IOJankMonitoringWindow::kIOJankInterval * 0.9);
396
397 constexpr auto kJankTiming =
398 internal::IOJankMonitoringWindow::kIOJankInterval * 1.3;
399 {
400 ScopedBlockingCall blocked_for_1s(FROM_HERE, BlockingType::MAY_BLOCK);
401 task_environment_->FastForwardBy(kJankTiming);
402 }
403
404 // No janks reported before the monitoring window completes.
405 EXPECT_THAT(reports_, ElementsAre());
406
407 task_environment_->FastForwardBy(
408 internal::IOJankMonitoringWindow::kMonitoringWindow);
409
410 EXPECT_THAT(reports_, ElementsAre(std::make_pair(1, 1)));
411 }
412
413 // Jank that lasts for 1.7 intervals should be rounded up to 2.
TEST_F(ScopedBlockingCallIOJankMonitoringTest,JankRoundUp)414 TEST_F(ScopedBlockingCallIOJankMonitoringTest, JankRoundUp) {
415 task_environment_->FastForwardBy(
416 internal::IOJankMonitoringWindow::kIOJankInterval * 0.5);
417
418 constexpr auto kJankTiming =
419 internal::IOJankMonitoringWindow::kIOJankInterval * 1.7;
420 {
421 ScopedBlockingCall blocked_for_1s(FROM_HERE, BlockingType::MAY_BLOCK);
422 task_environment_->FastForwardBy(kJankTiming);
423 }
424
425 // No janks reported before the monitoring window completes.
426 EXPECT_THAT(reports_, ElementsAre());
427
428 task_environment_->FastForwardBy(
429 internal::IOJankMonitoringWindow::kMonitoringWindow);
430
431 EXPECT_THAT(reports_, ElementsAre(std::make_pair(2, 2)));
432 }
433
434 // Start mid-interval and perform an operation that overlaps into the next one
435 // but is under the jank timing.
TEST_F(ScopedBlockingCallIOJankMonitoringTest,NoJankMidInterval)436 TEST_F(ScopedBlockingCallIOJankMonitoringTest, NoJankMidInterval) {
437 task_environment_->FastForwardBy(
438 internal::IOJankMonitoringWindow::kIOJankInterval / 3);
439
440 {
441 ScopedBlockingCall non_janky(FROM_HERE, BlockingType::MAY_BLOCK);
442 task_environment_->FastForwardBy(
443 internal::IOJankMonitoringWindow::kIOJankInterval - Milliseconds(1));
444 }
445
446 // No janks reported before the monitoring window completes.
447 EXPECT_THAT(reports_, ElementsAre());
448
449 task_environment_->FastForwardBy(
450 internal::IOJankMonitoringWindow::kMonitoringWindow);
451
452 EXPECT_THAT(reports_, ElementsAre(std::make_pair(0, 0)));
453 }
454
TEST_F(ScopedBlockingCallIOJankMonitoringTest,MultiThreaded)455 TEST_F(ScopedBlockingCallIOJankMonitoringTest, MultiThreaded) {
456 constexpr auto kJankTiming =
457 internal::IOJankMonitoringWindow::kIOJankInterval * 7;
458
459 // Every worker needs to block for precise clock management; hence we can't
460 // test beyond the TaskEnvironment's capacity.
461 const int kNumJankyTasks =
462 test::TaskEnvironment::kNumForegroundThreadPoolThreads;
463
464 TestWaitableEvent all_threads_blocked;
465 auto on_thread_blocked = BarrierClosure(
466 kNumJankyTasks,
467 BindOnce(&TestWaitableEvent::Signal, Unretained(&all_threads_blocked)));
468
469 TestWaitableEvent resume_all_threads;
470
471 for (int i = 0; i < kNumJankyTasks; ++i) {
472 base::ThreadPool::PostTask(
473 FROM_HERE, {MayBlock()}, BindLambdaForTesting([&] {
474 ScopedBlockingCall blocked_until_signal(FROM_HERE,
475 BlockingType::MAY_BLOCK);
476 on_thread_blocked.Run();
477
478 ScopedAllowBaseSyncPrimitivesForTesting allow_wait;
479 resume_all_threads.Wait();
480 }));
481 }
482
483 all_threads_blocked.Wait();
484 task_environment_->AdvanceClock(kJankTiming);
485 resume_all_threads.Signal();
486 task_environment_->RunUntilIdle();
487
488 // No janks reported before the monitoring window completes.
489 EXPECT_THAT(reports_, ElementsAre());
490
491 task_environment_->FastForwardBy(
492 internal::IOJankMonitoringWindow::kMonitoringWindow);
493
494 // Still only 7 janky internals, but more overall janks.
495 EXPECT_THAT(reports_, ElementsAre(std::make_pair(7, 7 * kNumJankyTasks)));
496 }
497
498 // 3 janks of 3 seconds; overlapping but starting 1 second apart from each
499 // other.
TEST_F(ScopedBlockingCallIOJankMonitoringTest,MultiThreadedOverlapped)500 TEST_F(ScopedBlockingCallIOJankMonitoringTest, MultiThreadedOverlapped) {
501 static const int kNumJankyTasks = 3;
502 static_assert(
503 kNumJankyTasks <= test::TaskEnvironment::kNumForegroundThreadPoolThreads,
504 "");
505
506 TestWaitableEvent next_task_is_blocked(WaitableEvent::ResetPolicy::AUTOMATIC);
507
508 TestWaitableEvent resume_thread[kNumJankyTasks] = {};
509 TestWaitableEvent exited_blocking_scope[kNumJankyTasks] = {};
510
511 auto blocking_task = BindLambdaForTesting([&](int task_index) {
512 {
513 // Simulate jank until |resume_thread[task_index]| is signaled.
514 ScopedBlockingCall blocked_until_signal(FROM_HERE,
515 BlockingType::MAY_BLOCK);
516 next_task_is_blocked.Signal();
517
518 ScopedAllowBaseSyncPrimitivesForTesting allow_wait;
519 resume_thread[task_index].Wait();
520 }
521 exited_blocking_scope[task_index].Signal();
522 });
523
524 // [0-1]s
525 base::ThreadPool::PostTask(FROM_HERE, {MayBlock()},
526 BindOnce(blocking_task, 0));
527 next_task_is_blocked.Wait();
528 task_environment_->AdvanceClock(
529 internal::IOJankMonitoringWindow::kIOJankInterval);
530
531 // [1-2]s
532 base::ThreadPool::PostTask(FROM_HERE, {MayBlock()},
533 BindOnce(blocking_task, 1));
534 next_task_is_blocked.Wait();
535 task_environment_->AdvanceClock(
536 internal::IOJankMonitoringWindow::kIOJankInterval);
537
538 // [2-3]s
539 base::ThreadPool::PostTask(FROM_HERE, {MayBlock()},
540 BindOnce(blocking_task, 2));
541 next_task_is_blocked.Wait();
542 task_environment_->AdvanceClock(
543 internal::IOJankMonitoringWindow::kIOJankInterval);
544
545 // [3-6]s
546 for (int i = 0; i < kNumJankyTasks; ++i) {
547 resume_thread[i].Signal();
548 exited_blocking_scope[i].Wait();
549 task_environment_->AdvanceClock(
550 internal::IOJankMonitoringWindow::kIOJankInterval);
551 }
552
553 // No janks reported before the monitoring window completes.
554 EXPECT_THAT(reports_, ElementsAre());
555
556 task_environment_->FastForwardBy(
557 internal::IOJankMonitoringWindow::kMonitoringWindow);
558
559 // 9s of total janks spread across 5 intervals.
560 EXPECT_THAT(reports_, ElementsAre(std::make_pair(5, 9)));
561 }
562
563 // 3 janks of 180 seconds; overlapping but starting 60s apart from each other.
564 // First one starting at 10 seconds (can't start later than that or we'll trip
565 // the kTimeDiscrepancyTimeout per TaskEnvironment's inability to RunUntilIdle()
566 // with pending blocked tasks).
TEST_F(ScopedBlockingCallIOJankMonitoringTest,MultiThreadedOverlappedWindows)567 TEST_F(ScopedBlockingCallIOJankMonitoringTest, MultiThreadedOverlappedWindows) {
568 constexpr int kNumJankyTasks = 3;
569 static_assert(
570 kNumJankyTasks <= test::TaskEnvironment::kNumForegroundThreadPoolThreads,
571 "");
572
573 TestWaitableEvent next_task_is_blocked(WaitableEvent::ResetPolicy::AUTOMATIC);
574
575 TestWaitableEvent resume_thread[kNumJankyTasks] = {};
576 TestWaitableEvent exited_blocking_scope[kNumJankyTasks] = {};
577
578 auto blocking_task = BindLambdaForTesting([&](int task_index) {
579 {
580 // Simulate jank until |resume_thread[task_index]| is signaled.
581 ScopedBlockingCall blocked_until_signal(FROM_HERE,
582 BlockingType::MAY_BLOCK);
583 next_task_is_blocked.Signal();
584
585 ScopedAllowBaseSyncPrimitivesForTesting allow_wait;
586 resume_thread[task_index].Wait();
587 }
588 exited_blocking_scope[task_index].Signal();
589 });
590
591 // [0-10s] (minus 1 ms to avoid reaching the timeout; this also tests the
592 // logic that intervals are rounded down to the starting interval (e.g.
593 // interval 9/60 in this case)).
594 task_environment_->AdvanceClock(
595 internal::IOJankMonitoringWindow::kTimeDiscrepancyTimeout -
596 Milliseconds(1));
597
598 // [10-70]s
599 base::ThreadPool::PostTask(FROM_HERE, {MayBlock()},
600 BindOnce(blocking_task, 0));
601 next_task_is_blocked.Wait();
602 task_environment_->AdvanceClock(
603 internal::IOJankMonitoringWindow::kMonitoringWindow);
604
605 // [70-130]s
606 base::ThreadPool::PostTask(FROM_HERE, {MayBlock()},
607 BindOnce(blocking_task, 1));
608 next_task_is_blocked.Wait();
609 task_environment_->AdvanceClock(
610 internal::IOJankMonitoringWindow::kMonitoringWindow);
611
612 // [130-190]s
613 base::ThreadPool::PostTask(FROM_HERE, {MayBlock()},
614 BindOnce(blocking_task, 2));
615 next_task_is_blocked.Wait();
616 task_environment_->AdvanceClock(
617 internal::IOJankMonitoringWindow::kMonitoringWindow);
618
619 // [190-370]s
620 for (int i = 0; i < kNumJankyTasks; ++i) {
621 resume_thread[i].Signal();
622 exited_blocking_scope[i].Wait();
623 task_environment_->AdvanceClock(
624 internal::IOJankMonitoringWindow::kMonitoringWindow);
625 }
626
627 // Already past the last window (relevant events end at 360s); flush the
628 // pending ripe delayed task that will complete the last window.
629 task_environment_->RunUntilIdle();
630
631 // 540s(180s*3) of total janks spread across 300 intervals in 6 windows.
632 // Distributed as such (zoomed out to 6 intervals per window):
633 // [011111]
634 // [122222]
635 // [233333]
636 // [322222]
637 // [21111]
638 // [100000]
639 // Starting at the 9th interval per the 10s-1ms offset start.
640 EXPECT_THAT(reports_,
641 ElementsAre(std::make_pair(51, 51), std::make_pair(60, 111),
642 std::make_pair(60, 171), std::make_pair(60, 129),
643 std::make_pair(60, 69), std::make_pair(9, 9)));
644 }
645
TEST_F(ScopedBlockingCallIOJankMonitoringTest,CancellationAcrossSleep)646 TEST_F(ScopedBlockingCallIOJankMonitoringTest, CancellationAcrossSleep) {
647 constexpr auto kJankTiming =
648 internal::IOJankMonitoringWindow::kIOJankInterval * 7;
649 {
650 ScopedBlockingCall blocked_for_7s(FROM_HERE, BlockingType::MAY_BLOCK);
651 task_environment_->FastForwardBy(kJankTiming);
652 }
653
654 // Jump just beyond the kTimeDiscrepancyTimeout for the next window.
655 task_environment_->AdvanceClock(
656 internal::IOJankMonitoringWindow::kMonitoringWindow +
657 internal::IOJankMonitoringWindow::kTimeDiscrepancyTimeout - kJankTiming);
658 task_environment_->RunUntilIdle();
659
660 // Window was canceled and previous jank was not reported.
661 EXPECT_THAT(reports_, ElementsAre());
662
663 // The second window should be independent and need a full kMonitoringWindow
664 // to elapse before reporting.
665 task_environment_->FastForwardBy(
666 internal::IOJankMonitoringWindow::kMonitoringWindow - Seconds(1));
667 EXPECT_THAT(reports_, ElementsAre());
668
669 task_environment_->FastForwardBy(Seconds(1));
670 EXPECT_THAT(reports_, ElementsAre(std::make_pair(0, 0)));
671 }
672
TEST_F(ScopedBlockingCallIOJankMonitoringTest,SleepWithLongJank)673 TEST_F(ScopedBlockingCallIOJankMonitoringTest, SleepWithLongJank) {
674 {
675 ScopedBlockingCall blocked_through_sleep(FROM_HERE,
676 BlockingType::MAY_BLOCK);
677
678 // Fast-forward 2 full windows and almost to the end of the 3rd.
679 task_environment_->FastForwardBy(
680 internal::IOJankMonitoringWindow::kMonitoringWindow * 3 - Seconds(1));
681
682 // Simulate a "sleep" over the timeout threshold.
683 task_environment_->AdvanceClock(
684 Seconds(1) + internal::IOJankMonitoringWindow::kTimeDiscrepancyTimeout);
685 }
686
687 // Two full jank windows are reported when the ScopedBlokcingCall unwinds but
688 // the 3rd is canceled.
689 EXPECT_THAT(reports_,
690 ElementsAre(std::make_pair(60, 60), std::make_pair(60, 60)));
691
692 // The 4th window has a new |start_time| so completing the "remaining delta"
693 // doesn't cause a report from the cancelled 3rd window.
694 task_environment_->FastForwardBy(
695 internal::IOJankMonitoringWindow::kMonitoringWindow - Seconds(1));
696 EXPECT_THAT(reports_,
697 ElementsAre(std::make_pair(60, 60), std::make_pair(60, 60)));
698
699 // Completing the whole 4th window generates a report.
700 task_environment_->FastForwardBy(Seconds(1));
701 EXPECT_THAT(reports_,
702 ElementsAre(std::make_pair(60, 60), std::make_pair(60, 60),
703 std::make_pair(0, 0)));
704 }
705
706 // Verifies that blocking calls on background workers aren't monitored.
707 // Platforms where !CanUseBackgroundThreadTypeForWorkerThread() will still
708 // monitor this jank (as it may interfere with other foreground work).
TEST_F(ScopedBlockingCallIOJankMonitoringTest,BackgroundBlockingCallsIgnored)709 TEST_F(ScopedBlockingCallIOJankMonitoringTest, BackgroundBlockingCallsIgnored) {
710 constexpr auto kJankTiming =
711 internal::IOJankMonitoringWindow::kIOJankInterval * 7;
712
713 TestWaitableEvent task_running;
714 TestWaitableEvent resume_task;
715
716 base::ThreadPool::PostTask(
717 FROM_HERE, {TaskPriority::BEST_EFFORT, MayBlock()},
718 BindLambdaForTesting([&] {
719 ScopedBlockingCall blocked_for_7s(FROM_HERE, BlockingType::MAY_BLOCK);
720 task_running.Signal();
721
722 ScopedAllowBaseSyncPrimitivesForTesting allow_wait;
723 resume_task.Wait();
724 }));
725
726 task_running.Wait();
727 task_environment_->AdvanceClock(kJankTiming);
728 resume_task.Signal();
729
730 // No janks reported before the monitoring window completes.
731 EXPECT_THAT(reports_, ElementsAre());
732
733 task_environment_->FastForwardBy(
734 internal::IOJankMonitoringWindow::kMonitoringWindow);
735
736 if (internal::CanUseBackgroundThreadTypeForWorkerThread())
737 EXPECT_THAT(reports_, ElementsAre(std::make_pair(0, 0)));
738 else
739 EXPECT_THAT(reports_, ElementsAre(std::make_pair(7, 7)));
740 }
741
TEST_F(ScopedBlockingCallIOJankMonitoringTest,BackgroundAndForegroundCallsMixed)742 TEST_F(ScopedBlockingCallIOJankMonitoringTest,
743 BackgroundAndForegroundCallsMixed) {
744 constexpr auto kJankTiming =
745 internal::IOJankMonitoringWindow::kIOJankInterval * 7;
746
747 TestWaitableEvent tasks_running;
748 auto on_task_running = BarrierClosure(
749 2, BindOnce(&TestWaitableEvent::Signal, Unretained(&tasks_running)));
750 TestWaitableEvent resume_tasks;
751
752 base::ThreadPool::PostTask(
753 FROM_HERE, {TaskPriority::BEST_EFFORT, MayBlock()},
754 BindLambdaForTesting([&] {
755 ScopedBlockingCall blocked_for_7s(FROM_HERE, BlockingType::MAY_BLOCK);
756 on_task_running.Run();
757
758 ScopedAllowBaseSyncPrimitivesForTesting allow_wait;
759 resume_tasks.Wait();
760 }));
761
762 base::ThreadPool::PostTask(
763 FROM_HERE, {TaskPriority::USER_BLOCKING, MayBlock()},
764 BindLambdaForTesting([&] {
765 ScopedBlockingCall blocked_for_7s(FROM_HERE, BlockingType::MAY_BLOCK);
766 on_task_running.Run();
767
768 ScopedAllowBaseSyncPrimitivesForTesting allow_wait;
769 resume_tasks.Wait();
770 }));
771
772 tasks_running.Wait();
773 task_environment_->AdvanceClock(kJankTiming);
774 resume_tasks.Signal();
775
776 // No janks reported before the monitoring window completes.
777 EXPECT_THAT(reports_, ElementsAre());
778
779 task_environment_->FastForwardBy(
780 internal::IOJankMonitoringWindow::kMonitoringWindow);
781
782 if (internal::CanUseBackgroundThreadTypeForWorkerThread())
783 EXPECT_THAT(reports_, ElementsAre(std::make_pair(7, 7)));
784 else
785 EXPECT_THAT(reports_, ElementsAre(std::make_pair(7, 14)));
786 }
787
TEST_F(ScopedBlockingCallIOJankMonitoringTest,WillBlockNotMonitored)788 TEST_F(ScopedBlockingCallIOJankMonitoringTest, WillBlockNotMonitored) {
789 constexpr auto kBlockedTiming =
790 internal::IOJankMonitoringWindow::kIOJankInterval * 7;
791 {
792 ScopedBlockingCall blocked_for_7s(FROM_HERE, BlockingType::WILL_BLOCK);
793 task_environment_->FastForwardBy(kBlockedTiming);
794 }
795
796 task_environment_->FastForwardBy(
797 internal::IOJankMonitoringWindow::kMonitoringWindow);
798
799 EXPECT_THAT(reports_, ElementsAre(std::make_pair(0, 0)));
800 }
801
TEST_F(ScopedBlockingCallIOJankMonitoringTest,NestedWillBlockCancelsMonitoring)802 TEST_F(ScopedBlockingCallIOJankMonitoringTest,
803 NestedWillBlockCancelsMonitoring) {
804 constexpr auto kBlockedTiming =
805 internal::IOJankMonitoringWindow::kIOJankInterval * 7;
806 {
807 ScopedBlockingCall blocked_for_14s(FROM_HERE, BlockingType::MAY_BLOCK);
808 task_environment_->FastForwardBy(kBlockedTiming);
809 ScopedBlockingCall will_block_for_7s(FROM_HERE, BlockingType::WILL_BLOCK);
810 task_environment_->FastForwardBy(kBlockedTiming);
811 }
812
813 task_environment_->FastForwardBy(
814 internal::IOJankMonitoringWindow::kMonitoringWindow);
815
816 EXPECT_THAT(reports_, ElementsAre(std::make_pair(0, 0)));
817 }
818
TEST_F(ScopedBlockingCallIOJankMonitoringTest,NestedMayBlockIgnored)819 TEST_F(ScopedBlockingCallIOJankMonitoringTest, NestedMayBlockIgnored) {
820 constexpr auto kBlockedTiming =
821 internal::IOJankMonitoringWindow::kIOJankInterval * 7;
822 {
823 ScopedBlockingCall blocked_for_14s(FROM_HERE, BlockingType::MAY_BLOCK);
824 task_environment_->FastForwardBy(kBlockedTiming);
825 ScopedBlockingCall may_block_for_7s(FROM_HERE, BlockingType::MAY_BLOCK);
826 task_environment_->FastForwardBy(kBlockedTiming);
827 }
828
829 task_environment_->FastForwardBy(
830 internal::IOJankMonitoringWindow::kMonitoringWindow);
831
832 EXPECT_THAT(reports_, ElementsAre(std::make_pair(14, 14)));
833 }
834
TEST_F(ScopedBlockingCallIOJankMonitoringTest,BaseSyncPrimitivesNotMonitored)835 TEST_F(ScopedBlockingCallIOJankMonitoringTest, BaseSyncPrimitivesNotMonitored) {
836 constexpr auto kBlockedTiming =
837 internal::IOJankMonitoringWindow::kIOJankInterval * 7;
838 {
839 // Even with MAY_BLOCK; base-sync-primitives aren't considered I/O jank
840 // (base-sync-primitives induced janks/hangs are captured by other tools,
841 // like Slow Reports and HangWatcher).
842 internal::ScopedBlockingCallWithBaseSyncPrimitives
843 base_sync_primitives_for_7s(FROM_HERE, BlockingType::MAY_BLOCK);
844 task_environment_->FastForwardBy(kBlockedTiming);
845 }
846
847 task_environment_->FastForwardBy(
848 internal::IOJankMonitoringWindow::kMonitoringWindow);
849
850 EXPECT_THAT(reports_, ElementsAre(std::make_pair(0, 0)));
851 }
852
TEST_F(ScopedBlockingCallIOJankMonitoringTest,NestedBaseSyncPrimitivesCancels)853 TEST_F(ScopedBlockingCallIOJankMonitoringTest,
854 NestedBaseSyncPrimitivesCancels) {
855 constexpr auto kBlockedTiming =
856 internal::IOJankMonitoringWindow::kIOJankInterval * 7;
857 {
858 ScopedBlockingCall blocked_for_14s(FROM_HERE, BlockingType::MAY_BLOCK);
859 task_environment_->FastForwardBy(kBlockedTiming);
860 internal::ScopedBlockingCallWithBaseSyncPrimitives
861 base_sync_primitives_for_7s(FROM_HERE, BlockingType::MAY_BLOCK);
862 task_environment_->FastForwardBy(kBlockedTiming);
863 }
864
865 task_environment_->FastForwardBy(
866 internal::IOJankMonitoringWindow::kMonitoringWindow);
867
868 EXPECT_THAT(reports_, ElementsAre(std::make_pair(0, 0)));
869 }
870
871 // Regression test for crbug.com/1209622
TEST_F(ScopedBlockingCallIOJankMonitoringTest,RacySampleNearMonitoringWindowBoundary)872 TEST_F(ScopedBlockingCallIOJankMonitoringTest,
873 RacySampleNearMonitoringWindowBoundary) {
874 constexpr auto kDeltaFromBoundary = Milliseconds(1);
875 const int kNumBlockedIntervals = 7;
876 constexpr auto kBlockedTiming =
877 internal::IOJankMonitoringWindow::kIOJankInterval * kNumBlockedIntervals;
878 // kBlockedTiming must be below kTimeDiscrepancyTimeout or racing worker
879 // threads might cancel the next window when ~ScopedBlockingCall lands too far
880 // in the future (since AdvanceClock() doesn't cause delayed tasks to run and
881 // the first window to expire when expected).
882 static_assert(kBlockedTiming <=
883 internal::IOJankMonitoringWindow::kTimeDiscrepancyTimeout,
884 "");
885
886 // Start this test near an IOJankMonitoringWindow boundary.
887 task_environment_->FastForwardBy(
888 internal::IOJankMonitoringWindow::kMonitoringWindow - kDeltaFromBoundary);
889
890 const int kNumRacingThreads =
891 test::TaskEnvironment::kNumForegroundThreadPoolThreads;
892
893 TestWaitableEvent all_threads_blocked;
894 auto on_thread_blocked = BarrierClosure(
895 kNumRacingThreads,
896 BindOnce(&TestWaitableEvent::Signal, Unretained(&all_threads_blocked)));
897 TestWaitableEvent unblock_worker_threads;
898
899 // First warmup the ThreadPool so there are kNumRacingThreads ready threads
900 // (to maximize the likelihood of a race).
901 for (int i = 0; i < kNumRacingThreads; ++i) {
902 ThreadPool::PostTask(FROM_HERE, {MayBlock()}, BindLambdaForTesting([&] {
903 on_thread_blocked.Run();
904 unblock_worker_threads.Wait();
905 }));
906 }
907 all_threads_blocked.Wait();
908 unblock_worker_threads.Signal();
909 task_environment_->RunUntilIdle();
910
911 all_threads_blocked.Reset();
912 on_thread_blocked = BarrierClosure(
913 kNumRacingThreads,
914 BindOnce(&TestWaitableEvent::Signal, Unretained(&all_threads_blocked)));
915 unblock_worker_threads.Reset();
916
917 for (int i = 0; i < kNumRacingThreads; ++i) {
918 ThreadPool::PostTask(FROM_HERE, {MayBlock()}, BindLambdaForTesting([&] {
919 ScopedBlockingCall blocked_for_14s(
920 FROM_HERE, BlockingType::MAY_BLOCK);
921 on_thread_blocked.Run();
922 unblock_worker_threads.Wait();
923 }));
924 }
925
926 // Race the worker threads sampling Now() at the start of their blocking call
927 // to reproduce the conditions of crbug.com/1209622. The race occurs if a
928 // worker thread samples Now() before it moves across the boundary but then
929 // the boundary is crossed before it sampled its assigned
930 // IOJankMonitoringWindow, getting a window which doesn't overlap with the
931 // sampled Now() identifying the ScopedBlockingCall's entry point.
932 task_environment_->AdvanceClock(kDeltaFromBoundary);
933 {
934 // We have to use AdvanceClock() above as a FastForwardBy() would stall on
935 // the blocked workers. This means the delayed task causing the first
936 // IOJankMonitoringWindow to expire didn't run. Entering a new
937 // ScopedBlockingCall forces this to happen.
938 ScopedBlockingCall trigger_window(FROM_HERE, BlockingType::MAY_BLOCK);
939 }
940
941 all_threads_blocked.Wait();
942 task_environment_->AdvanceClock(kBlockedTiming);
943 // If a worker thread holds a "begin" timestamp in the past versus its
944 // assigned IOJankMonitoringWindow, completing the janky ScopedBlockingCall
945 // will result in an OOB-index into
946 // |IOJankMonitoringWindow::intervals_jank_count_|.
947 unblock_worker_threads.Signal();
948 task_environment_->RunUntilIdle();
949
950 // Force a report immediately.
951 StopMonitoring();
952
953 // Test covered 2 monitoring windows.
954 ASSERT_EQ(reports_.size(), 2U);
955
956 // Between 0 and kNumRacingThreads sampled Now() and their
957 // IOJankMonitoringWindow before Now() was fast-forwarded by
958 // kDeltaFromBoundary.
959 auto [janky_intervals_count, total_jank_count] = reports_[0];
960 EXPECT_GE(janky_intervals_count, 0);
961 EXPECT_LE(janky_intervals_count, 1);
962 EXPECT_GE(total_jank_count, 0);
963 EXPECT_LE(total_jank_count, kNumRacingThreads);
964 std::tie(janky_intervals_count, total_jank_count) = reports_[1];
965 EXPECT_GE(janky_intervals_count, kNumBlockedIntervals - 1);
966 EXPECT_LE(janky_intervals_count, kNumBlockedIntervals);
967 EXPECT_GE(total_jank_count, (kNumBlockedIntervals - 1) * kNumRacingThreads);
968 EXPECT_LE(total_jank_count, kNumBlockedIntervals * kNumRacingThreads);
969 }
970
971 } // namespace base
972