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