scoped_blocking_call_unittest.cc 35 KB

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