/** * Copyright (C) 2020-present MongoDB, Inc. * * This program is free software: you can redistribute it and/or modify * it under the terms of the Server Side Public License, version 1, * as published by MongoDB, Inc. * * This program is distributed in the hope that it will be useful, * but WITHOUT ANY WARRANTY; without even the implied warranty of * MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the * Server Side Public License for more details. * * You should have received a copy of the Server Side Public License * along with this program. If not, see * . * * As a special exception, the copyright holders give permission to link the * code of portions of this program with the OpenSSL library under certain * conditions as described in each individual source file and distribute * linked combinations including the program with the OpenSSL library. You * must comply with the Server Side Public License in all respects for * all of the code used other than as permitted herein. If you modify file(s) * with this exception, you may extend this exception to your version of the * file(s), but you are not obligated to do so. If you do not wish to do so, * delete this exception statement from your version. If you delete this * exception statement from all source files in the program, then also delete * it in the license file. */ #include "mongo/db/operation_cpu_timer.h" #include "mongo/db/service_context_test_fixture.h" #include "mongo/logv2/log.h" #include "mongo/platform/atomic_word.h" #include "mongo/stdx/chrono.h" #include "mongo/stdx/condition_variable.h" #include "mongo/stdx/mutex.h" #include "mongo/stdx/thread.h" #include "mongo/unittest/barrier.h" #include "mongo/unittest/death_test.h" #include "mongo/unittest/unittest.h" #include "mongo/util/duration.h" #include "mongo/util/time_support.h" #define MONGO_LOGV2_DEFAULT_COMPONENT ::mongo::logv2::LogComponent::kTest namespace mongo { class OperationCPUTimerTest : public ServiceContextTest { public: auto makeClient() const { return getGlobalServiceContext()->makeClient("AlternativeClient"); } OperationCPUTimers* getTimers() const { return OperationCPUTimers::get(_opCtx.get()); } std::unique_ptr makeTimer() const { return getTimers()->makeTimer(); } void setUp() { _opCtx = getGlobalServiceContext()->makeOperationContext(Client::getCurrent()); } void busyWait(Nanoseconds delay) const { AtomicWord mayJoin{false}; stdx::thread blocker([&] { sleepFor(delay); mayJoin.store(true); }); while (!mayJoin.load()) { // Busy wait for the blocker thread. } blocker.join(); } void resetOpCtx() { _opCtx.reset(); } private: ServiceContext::UniqueOperationContext _opCtx; }; #if defined(__linux__) TEST_F(OperationCPUTimerTest, TestTimer) { auto timer = makeTimer(); timer->start(); busyWait(Microseconds(1)); // A small delay to make sure the timer advances. ASSERT_GT(timer->getElapsed(), Nanoseconds(0)); timer->stop(); const auto elapsedAfterStop = timer->getElapsed(); busyWait(Microseconds(10)); // A relatively longer delay to ensure the timer doesn't proceed. const auto elapsedAfterSleep = timer->getElapsed(); ASSERT_EQ(elapsedAfterStop, elapsedAfterSleep); } TEST_F(OperationCPUTimerTest, TestReset) { auto timer = makeTimer(); timer->start(); busyWait(Milliseconds(2)); // Introducing some delay for the timer to measure. timer->stop(); auto elapsedAfterStop = timer->getElapsed(); // Due to inconsistencies between the CPU time-based clock used in the timer and the // clock used in busyWait, the elapsed CPU time is sometimes observed as being less than the // time spent busy waiting. To account for that, only assert that at least 1ms of CPU time has // elapsed even though the thread was supposed to have busy-waited for 2ms. ASSERT_GTE(elapsedAfterStop, Milliseconds(1)); timer->start(); auto elapsedAfterReset = timer->getElapsed(); ASSERT_LT(elapsedAfterReset, elapsedAfterStop); } TEST_F(OperationCPUTimerTest, TestTimerDetachAndAttachHandlers) { unittest::Barrier failPointsReady{2}; stdx::thread observer([&] { FailPointEnableBlock fpAttach("hangCPUTimerAfterOnThreadAttach"); { FailPointEnableBlock fpDetach("hangCPUTimerAfterOnThreadDetach"); failPointsReady.countDownAndWait(); fpDetach->waitForTimesEntered(fpDetach.initialTimesEntered() + 1); } fpAttach->waitForTimesEntered(fpAttach.initialTimesEntered() + 1); }); auto timer1 = makeTimer(); timer1->start(); auto timer2 = makeTimer(); timer2->start(); failPointsReady.countDownAndWait(); { auto client = makeClient(); AlternativeClientRegion acr(client); } busyWait(Microseconds(1)); // A small delay to make sure the timers advance. timer1->stop(); timer2->stop(); observer.join(); ASSERT_GT(timer1->getElapsed(), Nanoseconds(0)); ASSERT_GT(timer2->getElapsed(), Nanoseconds(0)); } TEST_F(OperationCPUTimerTest, MultipleTimers) { auto timer1 = makeTimer(); timer1->start(); { auto timer2 = makeTimer(); timer2->start(); busyWait(Microseconds(1)); // A small delay to make sure the timers advance. ASSERT_GT(timer1->getElapsed(), Nanoseconds(0)); ASSERT_GT(timer2->getElapsed(), Nanoseconds(0)); ASSERT_EQ(2, getTimers()->count()); } ASSERT_EQ(1, getTimers()->count()); timer1->stop(); auto elapsedAfterStop = timer1->getElapsed(); busyWait(Milliseconds(10)); // A small delay to make sure the timer could advance. auto elapsedAfterSleep = timer1->getElapsed(); ASSERT_EQ(elapsedAfterSleep, elapsedAfterStop); } TEST_F(OperationCPUTimerTest, MultipleTimersOutOfOrder) { auto timer1 = makeTimer(); timer1->start(); auto timer2 = makeTimer(); timer2->start(); busyWait(Microseconds(1)); // A small delay to make sure the timers advance. ASSERT_GT(timer1->getElapsed(), Nanoseconds(0)); ASSERT_GT(timer2->getElapsed(), Nanoseconds(0)); // Note that there should be no restriction against stopping the first timer first. timer1->stop(); auto elapsedAfterStop = timer1->getElapsed(); busyWait(Milliseconds(10)); // A small delay to make sure the timer could advance. auto elapsedAfterSleep = timer1->getElapsed(); ASSERT_EQ(elapsedAfterSleep, elapsedAfterStop); timer2->stop(); ASSERT_GT(timer2->getElapsed(), elapsedAfterStop); elapsedAfterStop = timer2->getElapsed(); busyWait(Milliseconds(10)); // A small delay to make sure the timer could advance. elapsedAfterSleep = timer2->getElapsed(); ASSERT_EQ(elapsedAfterSleep, elapsedAfterStop); ASSERT_EQ(2, getTimers()->count()); } TEST_F(OperationCPUTimerTest, TestOpCtxDestruction) { auto timer = makeTimer(); timer->start(); resetOpCtx(); timer->stop(); } DEATH_TEST_F(OperationCPUTimerTest, StopTimerBeforeStart, "Timer is not running") { auto timer = makeTimer(); timer->stop(); } DEATH_TEST_F(OperationCPUTimerTest, StartTimerMultipleTimes, "Timer has already started") { auto timer = makeTimer(); timer->start(); timer->start(); } DEATH_TEST_F(OperationCPUTimerTest, OnAttachForAttachedTimer, "Timer has already been attached") { auto timer = makeTimer(); timer->start(); timer->onThreadAttach(); } DEATH_TEST_F(OperationCPUTimerTest, OnDetachForDetachedTimer, "Timer is not attached") { auto timer = makeTimer(); timer->start(); auto client = Client::releaseCurrent(); timer->onThreadDetach(); } DEATH_TEST_F(OperationCPUTimerTest, GetElapsedForPausedTimer, "Not attached to current thread") { auto timer = makeTimer(); timer->start(); auto client = Client::releaseCurrent(); timer->getElapsed(); } TEST_F(OperationCPUTimerTest, TimerPausesOnBlockingSleep) { // This test checks if the time measured by `OperationCPUTimer` does not include the period of // time the operation was blocked (e.g., waiting on a condition variable). The idea is to have // the operation block for `kSomeDelay`, ensure the elapsed time observed by the timer is always // less than `kSomeDelay`, and repeat the test `kRepeats` times. To account for the sporadic // wake ups, the test does not fail unless the number of failures exceeds `kMaxFailures`. This // is just a best-effort, and the number of failures is not guaranteed to not exceed the upper // bound (i.e., `kMaxFailures`). const auto kSomeDelay = Milliseconds(1); const auto kRepeats = 1000; const auto kMaxFailureRate = 0.1; const auto kMaxFailures = kMaxFailureRate * kRepeats; auto timer = makeTimer(); auto checkTimer = [&] { auto elapsed = timer->getElapsed(); if (elapsed < kSomeDelay) return true; LOGV2_WARNING(5160101, "Elapsed operation time exceeded the upper bound", "elapsed"_attr = elapsed, "delay"_attr = kSomeDelay); return false; }; auto failures = 0; for (auto i = 0; i < kRepeats; i++) { timer->start(); sleepFor(kSomeDelay); if (!checkTimer()) failures++; timer->stop(); stdx::condition_variable cv; auto mutex = MONGO_MAKE_LATCH("TimerPausesOnBlockingSleep"); timer->start(); stdx::unique_lock lk(mutex); cv.wait_for(lk, kSomeDelay.toSystemDuration(), [] { return false; }); if (!checkTimer()) failures++; timer->stop(); } ASSERT_LTE(failures, kMaxFailures); } #else TEST_F(OperationCPUTimerTest, TimerNotSetIfNotSupported) { auto timer = getTimers(); ASSERT(timer == nullptr); } #endif // defined(__linux__) } // namespace mongo