diff options
author | Louis Williams <louis.williams@mongodb.com> | 2023-02-10 08:11:54 +0000 |
---|---|---|
committer | Evergreen Agent <no-reply@evergreen.mongodb.com> | 2023-02-10 09:39:12 +0000 |
commit | d72f39af21ee012d54c0f49245790bc6d9119b6d (patch) | |
tree | 9eb64267ee2cbe5dcce81a15672a5e0752ec2df6 /src | |
parent | 188549516c293b65c2c3cba5ae05a573b2eab460 (diff) | |
download | mongo-d72f39af21ee012d54c0f49245790bc6d9119b6d.tar.gz |
SERVER-70032 Report CPU time in slow query logs and profiler as cpuNanos
Diffstat (limited to 'src')
28 files changed, 304 insertions, 111 deletions
diff --git a/src/mongo/db/catalog/drop_database.cpp b/src/mongo/db/catalog/drop_database.cpp index 5a83ec5bee5..bd5d3ac873a 100644 --- a/src/mongo/db/catalog/drop_database.cpp +++ b/src/mongo/db/catalog/drop_database.cpp @@ -138,9 +138,8 @@ Status _dropDatabase(OperationContext* opCtx, const DatabaseName& dbName, bool a str::stream() << "Dropping the '" << dbName << "' database is prohibited.", dbName != NamespaceString::kAdminDb); - // TODO (Kal): OldClientContext legacy, needs to be removed { - CurOp::get(opCtx)->ensureStarted(); + CurOp::get(opCtx)->ensureStarted(opCtx); stdx::lock_guard<Client> lk(*opCtx->getClient()); CurOp::get(opCtx)->setNS_inlock(dbName); } diff --git a/src/mongo/db/client.cpp b/src/mongo/db/client.cpp index acf26319b39..b5a8ccc246a 100644 --- a/src/mongo/db/client.cpp +++ b/src/mongo/db/client.cpp @@ -148,8 +148,8 @@ bool haveClient() { ServiceContext::UniqueClient Client::releaseCurrent() { invariant(haveClient(), "No client to release"); if (auto opCtx = currentClient->_opCtx) - if (auto timer = OperationCPUTimer::get(opCtx)) - timer->onThreadDetach(); + if (auto timers = OperationCPUTimers::get(opCtx)) + timers->onThreadDetach(); return std::move(currentClient); } @@ -157,8 +157,8 @@ void Client::setCurrent(ServiceContext::UniqueClient client) { invariantNoCurrentClient(); currentClient = std::move(client); if (auto opCtx = currentClient->_opCtx) - if (auto timer = OperationCPUTimer::get(opCtx)) - timer->onThreadAttach(); + if (auto timers = OperationCPUTimers::get(opCtx)) + timers->onThreadAttach(); } /** diff --git a/src/mongo/db/commands/dbcommands.cpp b/src/mongo/db/commands/dbcommands.cpp index ffb6201d72f..26620252c3b 100644 --- a/src/mongo/db/commands/dbcommands.cpp +++ b/src/mongo/db/commands/dbcommands.cpp @@ -633,9 +633,8 @@ public: NamespaceString::validDBName(dbname.db(), NamespaceString::DollarInDbNameBehavior::Allow)); - // TODO (Kal): OldClientContext legacy, needs to be removed { - CurOp::get(opCtx)->ensureStarted(); + CurOp::get(opCtx)->ensureStarted(opCtx); stdx::lock_guard<Client> lk(*opCtx->getClient()); CurOp::get(opCtx)->setNS_inlock(dbname); } @@ -676,9 +675,10 @@ public: } else { { stdx::lock_guard<Client> lk(*opCtx->getClient()); - // TODO: OldClientContext legacy, needs to be removed CurOp::get(opCtx)->enter_inlock( - dbname, CollectionCatalog::get(opCtx)->getDatabaseProfileLevel(dbname)); + opCtx, + dbname, + CollectionCatalog::get(opCtx)->getDatabaseProfileLevel(dbname)); } db->getStats(opCtx, &reply, cmd.getFreeStorage(), cmd.getScale()); diff --git a/src/mongo/db/commands/find_and_modify.cpp b/src/mongo/db/commands/find_and_modify.cpp index 2d0082285eb..4e9c4a6f3c7 100644 --- a/src/mongo/db/commands/find_and_modify.cpp +++ b/src/mongo/db/commands/find_and_modify.cpp @@ -369,7 +369,9 @@ write_ops::FindAndModifyCommandReply CmdFindAndModify::Invocation::writeConflict { stdx::lock_guard<Client> lk(*opCtx->getClient()); CurOp::get(opCtx)->enter_inlock( - nsString, CollectionCatalog::get(opCtx)->getDatabaseProfileLevel(nsString.dbName())); + opCtx, + nsString, + CollectionCatalog::get(opCtx)->getDatabaseProfileLevel(nsString.dbName())); } assertCanWrite_inlock(opCtx, nsString); @@ -433,7 +435,9 @@ write_ops::FindAndModifyCommandReply CmdFindAndModify::Invocation::writeConflict { stdx::lock_guard<Client> lk(*opCtx->getClient()); CurOp::get(opCtx)->enter_inlock( - nsString, CollectionCatalog::get(opCtx)->getDatabaseProfileLevel(nsString.dbName())); + opCtx, + nsString, + CollectionCatalog::get(opCtx)->getDatabaseProfileLevel(nsString.dbName())); } assertCanWrite_inlock(opCtx, nsString); diff --git a/src/mongo/db/curop.cpp b/src/mongo/db/curop.cpp index bd21ca2d7bb..01c358369f8 100644 --- a/src/mongo/db/curop.cpp +++ b/src/mongo/db/curop.cpp @@ -149,10 +149,6 @@ public: return retval; } - const OperationContext* opCtx() { - return _opCtx; - } - private: OperationContext* _opCtx = nullptr; @@ -374,21 +370,18 @@ void CurOp::setNS_inlock(const DatabaseName& dbName) { _nss = NamespaceString(dbName); } -TickSource::Tick CurOp::startTime() { - // It is legal for this function to get called multiple times, but all of those calls should be - // from the same thread, which should be the thread that "owns" this CurOp object. We define - // ownership here in terms of the Client object: each thread is associated with a Client - // (accessed by 'Client::getCurrent()'), which should be the same as the Client associated with - // this CurOp (by way of the OperationContext). Note that, if this is the "base" CurOp on the - // CurOpStack, then we don't yet hava an initialized pointer to the OperationContext, and we - // cannot perform this check. That is a rare case, however. - invariant(!_stack->opCtx() || Client::getCurrent() == _stack->opCtx()->getClient()); - +TickSource::Tick CurOp::startTime(OperationContext* opCtx) { auto start = _start.load(); if (start != 0) { return start; } + // Start the CPU timer if this system supports it. + if (auto cpuTimers = OperationCPUTimers::get(opCtx)) { + _cpuTimer = cpuTimers->makeTimer(); + _cpuTimer->start(); + } + // The '_start' value is initialized to 0 and gets assigned on demand the first time it gets // accessed. The above thread ownership requirement ensures that there will never be concurrent // calls to this '_start' assignment, but we use compare-exchange anyway as an additional check @@ -399,12 +392,11 @@ TickSource::Tick CurOp::startTime() { } void CurOp::done() { - // As documented in the 'CurOp::startTime()' member function, it is legal for this function to - // be called multiple times, but all calls must be in in the thread that "owns" this CurOp - // object. - invariant(!_stack->opCtx() || Client::getCurrent() == _stack->opCtx()->getClient()); - _end = _tickSource->getTicks(); + + if (_cpuTimer) { + _debug.cpuTime = _cpuTimer->getElapsed(); + } } Microseconds CurOp::computeElapsedTimeTotal(TickSource::Tick startTime, @@ -419,14 +411,14 @@ Microseconds CurOp::computeElapsedTimeTotal(TickSource::Tick startTime, return _tickSource->ticksTo<Microseconds>(endTime - startTime); } -void CurOp::enter_inlock(NamespaceString nss, int dbProfileLevel) { - ensureStarted(); +void CurOp::enter_inlock(OperationContext* opCtx, NamespaceString nss, int dbProfileLevel) { + ensureStarted(opCtx); _nss = std::move(nss); raiseDbProfileLevel(dbProfileLevel); } -void CurOp::enter_inlock(const DatabaseName& dbName, int dbProfileLevel) { - enter_inlock(NamespaceString(dbName), dbProfileLevel); +void CurOp::enter_inlock(OperationContext* opCtx, const DatabaseName& dbName, int dbProfileLevel) { + enter_inlock(opCtx, NamespaceString(dbName), dbProfileLevel); } void CurOp::raiseDbProfileLevel(int dbProfileLevel) { @@ -1019,6 +1011,10 @@ void OpDebug::report(OperationContext* opCtx, pAttrs->add("operationMetrics", builder.obj()); } + if (cpuTime > Nanoseconds::zero()) { + pAttrs->add("cpuNanos", durationCount<Nanoseconds>(cpuTime)); + } + if (client && client->session()) { pAttrs->add("remote", client->session()->remote()); } @@ -1200,6 +1196,10 @@ void OpDebug::append(OperationContext* opCtx, b.append("remoteOpWaitMillis", durationCount<Milliseconds>(*remoteOpWaitTime)); } + if (cpuTime > Nanoseconds::zero()) { + b.appendNumber("cpuNanos", durationCount<Nanoseconds>(cpuTime)); + } + b.appendNumber("millis", durationCount<Milliseconds>(executionTime)); if (!curop.getPlanSummary().empty()) { @@ -1505,6 +1505,12 @@ std::function<BSONObj(ProfileFilter::Args)> OpDebug::appendStaged(StringSet requ } }); + addIfNeeded("cpuNanos", [](auto field, auto args, auto& b) { + if (args.op.cpuTime > Nanoseconds::zero()) { + b.appendNumber(field, durationCount<Nanoseconds>(args.op.cpuTime)); + } + }); + // millis and durationMillis are the same thing. This is one of the few inconsistencies between // the profiler (OpDebug::append) and the log file (OpDebug::report), so for the profile filter // we support both names. diff --git a/src/mongo/db/curop.h b/src/mongo/db/curop.h index e939e22ff9c..a0cd46a4e0e 100644 --- a/src/mongo/db/curop.h +++ b/src/mongo/db/curop.h @@ -297,6 +297,11 @@ public: // response info Microseconds executionTime{0}; + + // Amount of CPU time used by this thread. Will remain zero if this platform does not support + // this feature. + Nanoseconds cpuTime{0}; + long long nreturned{-1}; int responseLength{-1}; @@ -453,8 +458,8 @@ public: return _originatingCommand; } - void enter_inlock(NamespaceString nss, int dbProfileLevel); - void enter_inlock(const DatabaseName& dbName, int dbProfileLevel); + void enter_inlock(OperationContext* opCtx, NamespaceString nss, int dbProfileLevel); + void enter_inlock(OperationContext* opCtx, const DatabaseName& dbName, int dbProfileLevel); /** * Sets the type of the current network operation. @@ -575,8 +580,8 @@ public: // negative, if the system time has been reset during the course of this operation. // - void ensureStarted() { - static_cast<void>(startTime()); + void ensureStarted(OperationContext* opCtx) { + static_cast<void>(startTime(opCtx)); } bool isStarted() const { return _start.load() != 0; @@ -881,7 +886,7 @@ public: private: class CurOpStack; - TickSource::Tick startTime(); + TickSource::Tick startTime(OperationContext* opCtx); Microseconds computeElapsedTimeTotal(TickSource::Tick startTime, TickSource::Tick endTime) const; @@ -910,6 +915,10 @@ private: // The time at which this CurOp instance was marked as done or 0 if the CurOp is not yet done. std::atomic<TickSource::Tick> _end{0}; // NOLINT + // This CPU timer tracks the CPU time spent for this operation. Will be nullptr on unsupported + // platforms. + std::unique_ptr<OperationCPUTimer> _cpuTimer; + // The time at which this CurOp instance had its timer paused, or 0 if the timer is not // currently paused. TickSource::Tick _lastPauseTime{0}; diff --git a/src/mongo/db/curop_test.cpp b/src/mongo/db/curop_test.cpp index 47c2289baae..d944a29f1de 100644 --- a/src/mongo/db/curop_test.cpp +++ b/src/mongo/db/curop_test.cpp @@ -257,7 +257,7 @@ TEST(CurOpTest, ElapsedTimeReflectsTickSource) { ASSERT_FALSE(curop->isStarted()); - curop->ensureStarted(); + curop->ensureStarted(opCtx.get()); ASSERT_TRUE(curop->isStarted()); tickSourceMock->advance(Milliseconds{20}); diff --git a/src/mongo/db/db_raii.cpp b/src/mongo/db/db_raii.cpp index f9544eab063..a2e8213dbb5 100644 --- a/src/mongo/db/db_raii.cpp +++ b/src/mongo/db/db_raii.cpp @@ -486,7 +486,7 @@ AutoStatsTracker::AutoStatsTracker( } stdx::lock_guard<Client> clientLock(*_opCtx->getClient()); - CurOp::get(_opCtx)->enter_inlock(nss, dbProfilingLevel); + CurOp::get(_opCtx)->enter_inlock(opCtx, nss, dbProfilingLevel); } AutoStatsTracker::~AutoStatsTracker() { @@ -1506,8 +1506,8 @@ OldClientContext::OldClientContext(OperationContext* opCtx, } stdx::lock_guard<Client> lk(*_opCtx->getClient()); - currentOp->enter_inlock(nss, - CollectionCatalog::get(opCtx)->getDatabaseProfileLevel(_db->name())); + currentOp->enter_inlock( + opCtx, nss, CollectionCatalog::get(opCtx)->getDatabaseProfileLevel(_db->name())); } AutoGetCollectionForReadCommandMaybeLockFree::AutoGetCollectionForReadCommandMaybeLockFree( diff --git a/src/mongo/db/db_raii_test.cpp b/src/mongo/db/db_raii_test.cpp index ce6099b6b68..6f3bb7efcea 100644 --- a/src/mongo/db/db_raii_test.cpp +++ b/src/mongo/db/db_raii_test.cpp @@ -74,7 +74,7 @@ std::unique_ptr<PlanExecutor, PlanExecutor::Deleter> makeTailableQueryPlan( awaitDataState(opCtx).shouldWaitForInserts = true; awaitDataState(opCtx).waitForInsertsDeadline = opCtx->getServiceContext()->getPreciseClockSource()->now() + Seconds(1); - CurOp::get(opCtx)->ensureStarted(); + CurOp::get(opCtx)->ensureStarted(opCtx); const boost::intrusive_ptr<ExpressionContext> expCtx; diff --git a/src/mongo/db/index_builds_coordinator.cpp b/src/mongo/db/index_builds_coordinator.cpp index ae089d0f721..2cd9604a5cf 100644 --- a/src/mongo/db/index_builds_coordinator.cpp +++ b/src/mongo/db/index_builds_coordinator.cpp @@ -356,7 +356,7 @@ void updateCurOpForCommitOrAbort(OperationContext* opCtx, StringData fieldName, auto opDescObj = builder.obj(); curOp->setLogicalOp_inlock(LogicalOp::opCommand); curOp->setOpDescription_inlock(opDescObj); - curOp->ensureStarted(); + curOp->ensureStarted(opCtx); } /** @@ -1908,7 +1908,7 @@ void IndexBuildsCoordinator::updateCurOpOpDescription(OperationContext* opCtx, curOp->setLogicalOp_inlock(LogicalOp::opCommand); curOp->setOpDescription_inlock(opDescObj); curOp->setNS_inlock(nss); - curOp->ensureStarted(); + curOp->ensureStarted(opCtx); } Status IndexBuildsCoordinator::_setUpIndexBuildForTwoPhaseRecovery( diff --git a/src/mongo/db/operation_cpu_timer.cpp b/src/mongo/db/operation_cpu_timer.cpp index b4c58483d82..88f275dd137 100644 --- a/src/mongo/db/operation_cpu_timer.cpp +++ b/src/mongo/db/operation_cpu_timer.cpp @@ -73,6 +73,9 @@ MONGO_FAIL_POINT_DEFINE(hangCPUTimerAfterOnThreadDetach); class PosixTimer final : public OperationCPUTimer { public: + PosixTimer(const std::shared_ptr<OperationCPUTimers>& timers) : OperationCPUTimer(timers) {} + ~PosixTimer() = default; + Nanoseconds getElapsed() const override; void start() override; @@ -157,14 +160,13 @@ Nanoseconds PosixTimer::_getThreadTime() const try { LOGV2_FATAL(4744601, "Failed to read the CPU time for the current thread", "error"_attr = ex); } -static auto getCPUTimer = OperationContext::declareDecoration<PosixTimer>(); +// Set of timers created by this OperationContext. +static auto getCPUTimers = + OperationContext::declareDecoration<std::shared_ptr<OperationCPUTimers>>(); } // namespace -OperationCPUTimer* OperationCPUTimer::get(OperationContext* opCtx) { - invariant(Client::getCurrent() && Client::getCurrent()->getOperationContext() == opCtx, - "Operation not attached to the current thread"); - +OperationCPUTimers* OperationCPUTimers::get(OperationContext* opCtx) { // Checks for time support on POSIX platforms. In particular, it checks for support in presence // of SMP systems. static bool isTimeSupported = [] { @@ -184,15 +186,67 @@ OperationCPUTimer* OperationCPUTimer::get(OperationContext* opCtx) { if (!isTimeSupported) return nullptr; - return &getCPUTimer(opCtx); + + auto& timers = getCPUTimers(opCtx); + if (!timers) { + timers = std::make_shared<OperationCPUTimers>(); + } + return timers.get(); +} + +std::unique_ptr<OperationCPUTimer> OperationCPUTimers::makeTimer() { + return std::make_unique<PosixTimer>(shared_from_this()); } #else // not defined(__linux__) -OperationCPUTimer* OperationCPUTimer::get(OperationContext*) { +OperationCPUTimers* OperationCPUTimers::get(OperationContext*) { return nullptr; } +std::unique_ptr<OperationCPUTimer> OperationCPUTimers::makeTimer() { + MONGO_UNREACHABLE; +} + #endif // defined(__linux__) +OperationCPUTimer::OperationCPUTimer(const std::shared_ptr<OperationCPUTimers>& timers) + : _timers(timers) { + _it = timers->_add(this); +} + +OperationCPUTimer::~OperationCPUTimer() { + // It is possible for an OperationCPUTimer to outlive the OperationCPUTimers container that is + // decorated on the OperationContext. For example, a Timer can be owned by an OperationContext + // decoration, and may be destructed after the Timers container, an order which we cannot + // control. Therefore we must ensure the weak_ptr we hold is still valid. + if (auto timers = _timers.lock()) { + timers->_remove(_it); + } +} + +OperationCPUTimers::Iterator OperationCPUTimers::_add(OperationCPUTimer* timer) { + return _timers.insert(_timers.end(), timer); +} + +void OperationCPUTimers::_remove(OperationCPUTimers::Iterator it) { + _timers.erase(it); +} + +size_t OperationCPUTimers::count() const { + return _timers.size(); +} + +void OperationCPUTimers::onThreadAttach() { + for (auto& timer : _timers) { + timer->onThreadAttach(); + } +} + +void OperationCPUTimers::onThreadDetach() { + for (auto& timer : _timers) { + timer->onThreadDetach(); + } +} + } // namespace mongo diff --git a/src/mongo/db/operation_cpu_timer.h b/src/mongo/db/operation_cpu_timer.h index 0cd0b88acba..1ac0f5c93cd 100644 --- a/src/mongo/db/operation_cpu_timer.h +++ b/src/mongo/db/operation_cpu_timer.h @@ -29,11 +29,48 @@ #pragma once +#include <list> + #include "mongo/util/duration.h" namespace mongo { class OperationContext; +class OperationCPUTimer; + +/** + * Allocates and tracks CPU timers for an OperationContext. + */ +class OperationCPUTimers : public std::enable_shared_from_this<OperationCPUTimers> { +public: + friend class OperationCPUTimer; + + /** + * Returns `nullptr` if the platform does not support tracking of CPU consumption. + */ + static OperationCPUTimers* get(OperationContext*); + + /** + * Returns a timer bound to this OperationContext and the threads that it runs on. Timers + * created from this function may safely outlive the OperationCPUTimers container and the + * OperationContext, but only to simplify destruction ordering problems. + */ + std::unique_ptr<OperationCPUTimer> makeTimer(); + + void onThreadAttach(); + void onThreadDetach(); + + size_t count() const; + +private: + using Iterator = std::list<mongo::OperationCPUTimer*>::iterator; + Iterator _add(OperationCPUTimer* timer); + void _remove(Iterator it); + + // List of active timers on this OperationContext. When an OperationCPUTimer is constructed, it + // will add itself to this list and remove itself on destruction. + std::list<OperationCPUTimer*> _timers; +}; /** * Implements the CPU timer for platforms that support CPU consumption tracking. Consider the @@ -54,10 +91,8 @@ class OperationContext; */ class OperationCPUTimer { public: - /** - * Returns `nullptr` if the platform does not support tracking of CPU consumption. - */ - static OperationCPUTimer* get(OperationContext*); + OperationCPUTimer(const std::shared_ptr<OperationCPUTimers>& timers); + virtual ~OperationCPUTimer(); virtual Nanoseconds getElapsed() const = 0; @@ -66,6 +101,18 @@ public: virtual void onThreadAttach() = 0; virtual void onThreadDetach() = 0; + + // Called by owning operation to indicate that the operation has ended and any pointers to the + // OperationCPUTimers are no longer valid. The timer will continue to function correctly. + void onOperationEnded(); + +private: + // Weak reference to OperationContext-owned tracked list of timers. The Timers container can be + // destructed before this Timer. + std::weak_ptr<OperationCPUTimers> _timers; + + // Iterator position to speed up deletion from the list of timers for this operation. + OperationCPUTimers::Iterator _it; }; } // namespace mongo diff --git a/src/mongo/db/operation_cpu_timer_test.cpp b/src/mongo/db/operation_cpu_timer_test.cpp index 457c5c2c974..54f2785a6ff 100644 --- a/src/mongo/db/operation_cpu_timer_test.cpp +++ b/src/mongo/db/operation_cpu_timer_test.cpp @@ -53,8 +53,12 @@ public: return getGlobalServiceContext()->makeClient("AlternativeClient"); } - auto getTimer() const { - return OperationCPUTimer::get(_opCtx.get()); + OperationCPUTimers* getTimers() const { + return OperationCPUTimers::get(_opCtx.get()); + } + + std::unique_ptr<OperationCPUTimer> makeTimer() const { + return getTimers()->makeTimer(); } void setUp() { @@ -73,6 +77,10 @@ public: blocker.join(); } + void resetOpCtx() { + _opCtx.reset(); + } + private: ServiceContext::UniqueOperationContext _opCtx; }; @@ -80,7 +88,7 @@ private: #if defined(__linux__) TEST_F(OperationCPUTimerTest, TestTimer) { - auto timer = getTimer(); + auto timer = makeTimer(); timer->start(); busyWait(Microseconds(1)); // A small delay to make sure the timer advances. @@ -94,7 +102,7 @@ TEST_F(OperationCPUTimerTest, TestTimer) { } TEST_F(OperationCPUTimerTest, TestReset) { - auto timer = getTimer(); + auto timer = makeTimer(); timer->start(); busyWait(Milliseconds(1)); // Introducing some delay for the timer to measure. @@ -114,13 +122,16 @@ TEST_F(OperationCPUTimerTest, TestTimerDetachAndAttachHandlers) { { FailPointEnableBlock fpDetach("hangCPUTimerAfterOnThreadDetach"); failPointsReady.countDownAndWait(); - fpDetach->waitForTimesEntered(1); + fpDetach->waitForTimesEntered(fpDetach.initialTimesEntered() + 1); } - fpAttach->waitForTimesEntered(1); + fpAttach->waitForTimesEntered(fpAttach.initialTimesEntered() + 1); }); - auto timer = getTimer(); - timer->start(); + auto timer1 = makeTimer(); + timer1->start(); + + auto timer2 = makeTimer(); + timer2->start(); failPointsReady.countDownAndWait(); { @@ -128,41 +139,103 @@ TEST_F(OperationCPUTimerTest, TestTimerDetachAndAttachHandlers) { AlternativeClientRegion acr(client); } - timer->stop(); + 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)); } -DEATH_TEST_F(OperationCPUTimerTest, - AccessTimerForDetachedOperation, - "Operation not attached to the current thread") { - auto client = Client::releaseCurrent(); - getTimer(); +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") { - getTimer()->stop(); + auto timer = makeTimer(); + timer->stop(); } DEATH_TEST_F(OperationCPUTimerTest, StartTimerMultipleTimes, "Timer has already started") { - getTimer()->start(); - getTimer()->start(); + auto timer = makeTimer(); + timer->start(); + timer->start(); } DEATH_TEST_F(OperationCPUTimerTest, OnAttachForAttachedTimer, "Timer has already been attached") { - auto timer = getTimer(); + auto timer = makeTimer(); timer->start(); timer->onThreadAttach(); } DEATH_TEST_F(OperationCPUTimerTest, OnDetachForDetachedTimer, "Timer is not attached") { - auto timer = getTimer(); + auto timer = makeTimer(); timer->start(); auto client = Client::releaseCurrent(); timer->onThreadDetach(); } DEATH_TEST_F(OperationCPUTimerTest, GetElapsedForPausedTimer, "Not attached to current thread") { - auto timer = getTimer(); + auto timer = makeTimer(); timer->start(); auto client = Client::releaseCurrent(); timer->getElapsed(); @@ -181,7 +254,7 @@ TEST_F(OperationCPUTimerTest, TimerPausesOnBlockingSleep) { const auto kMaxFailureRate = 0.1; const auto kMaxFailures = kMaxFailureRate * kRepeats; - auto timer = getTimer(); + auto timer = makeTimer(); auto checkTimer = [&] { auto elapsed = timer->getElapsed(); @@ -218,7 +291,7 @@ TEST_F(OperationCPUTimerTest, TimerPausesOnBlockingSleep) { #else TEST_F(OperationCPUTimerTest, TimerNotSetIfNotSupported) { - auto timer = getTimer(); + auto timer = getTimers(); ASSERT(timer == nullptr); } diff --git a/src/mongo/db/ops/write_ops_exec.cpp b/src/mongo/db/ops/write_ops_exec.cpp index 71d6531de1a..d0543d27294 100644 --- a/src/mongo/db/ops/write_ops_exec.cpp +++ b/src/mongo/db/ops/write_ops_exec.cpp @@ -664,7 +664,7 @@ WriteResult performInserts(OperationContext* opCtx, stdx::lock_guard<Client> lk(*opCtx->getClient()); curOp.setNS_inlock(wholeOp.getNamespace()); curOp.setLogicalOp_inlock(LogicalOp::opInsert); - curOp.ensureStarted(); + curOp.ensureStarted(opCtx); curOp.debug().additiveMetrics.ninserted = 0; } @@ -967,7 +967,7 @@ static SingleWriteResult performSingleUpdateOpWithDupKeyRetry( curOp.setNetworkOp_inlock(dbUpdate); curOp.setLogicalOp_inlock(LogicalOp::opUpdate); curOp.setOpDescription_inlock(op.toBSON()); - curOp.ensureStarted(); + curOp.ensureStarted(opCtx); } uassert(ErrorCodes::InvalidOptions, @@ -1181,7 +1181,7 @@ static SingleWriteResult performSingleDeleteOp(OperationContext* opCtx, curOp.setNetworkOp_inlock(dbDelete); curOp.setLogicalOp_inlock(LogicalOp::opDelete); curOp.setOpDescription_inlock(op.toBSON()); - curOp.ensureStarted(); + curOp.ensureStarted(opCtx); } auto request = DeleteRequest{}; @@ -2714,7 +2714,7 @@ write_ops::InsertCommandReply performTimeseriesWrites( stdx::lock_guard<Client> lk(*opCtx->getClient()); curOp.setNS_inlock(ns(request)); curOp.setLogicalOp_inlock(LogicalOp::opInsert); - curOp.ensureStarted(); + curOp.ensureStarted(opCtx); curOp.debug().additiveMetrics.ninserted = 0; } diff --git a/src/mongo/db/pipeline/document_source_merge_cursors_test.cpp b/src/mongo/db/pipeline/document_source_merge_cursors_test.cpp index b0c6fff8037..e652aba8588 100644 --- a/src/mongo/db/pipeline/document_source_merge_cursors_test.cpp +++ b/src/mongo/db/pipeline/document_source_merge_cursors_test.cpp @@ -115,7 +115,7 @@ public: setupShards(shards); - CurOp::get(operationContext())->ensureStarted(); + CurOp::get(operationContext())->ensureStarted(operationContext()); } boost::intrusive_ptr<ExpressionContext> getExpCtx() { diff --git a/src/mongo/db/repl/replication_coordinator_impl.cpp b/src/mongo/db/repl/replication_coordinator_impl.cpp index 58a6127b885..9b6e91f4800 100644 --- a/src/mongo/db/repl/replication_coordinator_impl.cpp +++ b/src/mongo/db/repl/replication_coordinator_impl.cpp @@ -4233,7 +4233,7 @@ void ReplicationCoordinatorImpl::_reconfigToRemoveNewlyAddedField( curOp->setOpDescription_inlock(bob.obj()); // TODO SERVER-62491 Use systemTenantId. curOp->setNS_inlock(NamespaceString(boost::none, "local.system.replset")); - curOp->ensureStarted(); + curOp->ensureStarted(opCtx.get()); } if (MONGO_unlikely(hangDuringAutomaticReconfig.shouldFail())) { diff --git a/src/mongo/db/s/config/initial_split_policy.cpp b/src/mongo/db/s/config/initial_split_policy.cpp index 807661e6b88..af9a2393278 100644 --- a/src/mongo/db/s/config/initial_split_policy.cpp +++ b/src/mongo/db/s/config/initial_split_policy.cpp @@ -703,7 +703,7 @@ BSONObjSet SamplingBasedSplitPolicy::createFirstSplitPoints(OperationContext* op // The BlockingResultsMerger underlying the $mergeCursors stage records how long was // spent waiting for samples from the donor shards. It doing so requires the CurOp // to be marked as having started. - CurOp::get(opCtx)->ensureStarted(); + CurOp::get(opCtx)->ensureStarted(opCtx); _appendSplitPointsFromSample( &splitPoints, shardKey, _numInitialChunks - splitPoints.size() - 1); diff --git a/src/mongo/db/s/global_index/global_index_cloner_fetcher.cpp b/src/mongo/db/s/global_index/global_index_cloner_fetcher.cpp index 03bfea8a74c..b12557caaca 100644 --- a/src/mongo/db/s/global_index/global_index_cloner_fetcher.cpp +++ b/src/mongo/db/s/global_index/global_index_cloner_fetcher.cpp @@ -261,7 +261,7 @@ std::unique_ptr<Pipeline, PipelineDeleter> GlobalIndexClonerFetcher::_restartPip // recipient spent waiting for documents from the donor shards. It doing so requires the CurOp // to be marked as having started. auto* curOp = CurOp::get(opCtx); - curOp->ensureStarted(); + curOp->ensureStarted(opCtx); ON_BLOCK_EXIT([curOp] { curOp->done(); }); auto pipeline = _targetAggregationRequest(*makePipeline(opCtx)); diff --git a/src/mongo/db/s/periodic_sharded_index_consistency_checker.cpp b/src/mongo/db/s/periodic_sharded_index_consistency_checker.cpp index fb5b113216d..7a3b489674e 100644 --- a/src/mongo/db/s/periodic_sharded_index_consistency_checker.cpp +++ b/src/mongo/db/s/periodic_sharded_index_consistency_checker.cpp @@ -121,7 +121,7 @@ void PeriodicShardedIndexConsistencyChecker::_launchShardedIndexConsistencyCheck auto uniqueOpCtx = client->makeOperationContext(); auto opCtx = uniqueOpCtx.get(); auto curOp = CurOp::get(opCtx); - curOp->ensureStarted(); + curOp->ensureStarted(opCtx); ON_BLOCK_EXIT([&] { curOp->done(); }); try { diff --git a/src/mongo/db/s/resharding/resharding_collection_cloner.cpp b/src/mongo/db/s/resharding/resharding_collection_cloner.cpp index ff5f03d3a35..384c07ebb72 100644 --- a/src/mongo/db/s/resharding/resharding_collection_cloner.cpp +++ b/src/mongo/db/s/resharding/resharding_collection_cloner.cpp @@ -232,7 +232,7 @@ std::unique_ptr<Pipeline, PipelineDeleter> ReshardingCollectionCloner::_restartP // recipient spent waiting for documents from the donor shards. It doing so requires the CurOp // to be marked as having started. auto* curOp = CurOp::get(opCtx); - curOp->ensureStarted(); + curOp->ensureStarted(opCtx); ON_BLOCK_EXIT([curOp] { curOp->done(); }); auto pipeline = _targetAggregationRequest( diff --git a/src/mongo/db/s/resharding/resharding_data_copy_util.cpp b/src/mongo/db/s/resharding/resharding_data_copy_util.cpp index d5fbd3d2bc1..5bfde9adf0d 100644 --- a/src/mongo/db/s/resharding/resharding_data_copy_util.cpp +++ b/src/mongo/db/s/resharding/resharding_data_copy_util.cpp @@ -212,8 +212,9 @@ std::vector<InsertStatement> fillBatchForInsert(Pipeline& pipeline, int batchSiz // The BlockingResultsMerger underlying by the $mergeCursors stage records how long the // recipient spent waiting for documents from the donor shards. It doing so requires the CurOp // to be marked as having started. - auto* curOp = CurOp::get(pipeline.getContext()->opCtx); - curOp->ensureStarted(); + auto opCtx = pipeline.getContext()->opCtx; + auto* curOp = CurOp::get(opCtx); + curOp->ensureStarted(opCtx); ON_BLOCK_EXIT([curOp] { curOp->done(); }); std::vector<InsertStatement> batch; diff --git a/src/mongo/db/s/resharding/resharding_txn_cloner.cpp b/src/mongo/db/s/resharding/resharding_txn_cloner.cpp index 8a015e52af5..75c652f9bb8 100644 --- a/src/mongo/db/s/resharding/resharding_txn_cloner.cpp +++ b/src/mongo/db/s/resharding/resharding_txn_cloner.cpp @@ -157,7 +157,7 @@ boost::optional<SessionTxnRecord> ReshardingTxnCloner::_getNextRecord(OperationC // recipient spent waiting for documents from the donor shard. It doing so requires the CurOp to // be marked as having started. auto* curOp = CurOp::get(opCtx); - curOp->ensureStarted(); + curOp->ensureStarted(opCtx); ON_BLOCK_EXIT([curOp] { curOp->done(); }); auto doc = pipeline.getNext(); diff --git a/src/mongo/db/service_entry_point_common.cpp b/src/mongo/db/service_entry_point_common.cpp index e86eb1a921d..3b0499abfb2 100644 --- a/src/mongo/db/service_entry_point_common.cpp +++ b/src/mongo/db/service_entry_point_common.cpp @@ -1538,7 +1538,7 @@ void ExecCommandDatabase::_initiateCommand() { } if (CommandHelpers::isHelpRequest(helpField)) { - CurOp::get(opCtx)->ensureStarted(); + CurOp::get(opCtx)->ensureStarted(opCtx); // We disable not-primary-error tracker for help requests due to SERVER-11492, because // config servers use help requests to determine which commands are database writes, and so // must be forwarded to all config servers. @@ -1742,7 +1742,7 @@ void ExecCommandDatabase::_initiateCommand() { uassertStatusOK(status); } - CurOp::get(opCtx)->ensureStarted(); + CurOp::get(opCtx)->ensureStarted(opCtx); command->incrementCommandsExecuted(); diff --git a/src/mongo/db/stats/resource_consumption_metrics.cpp b/src/mongo/db/stats/resource_consumption_metrics.cpp index 1fccd04fc66..ee3b062e168 100644 --- a/src/mongo/db/stats/resource_consumption_metrics.cpp +++ b/src/mongo/db/stats/resource_consumption_metrics.cpp @@ -328,9 +328,9 @@ void ResourceConsumption::MetricsCollector::beginScopedCollecting(OperationConte _collecting = ScopedCollectionState::kInScopeCollecting; _hasCollectedMetrics = true; - // The OperationCPUTimer may be nullptr on unsupported systems. - _metrics.cpuTimer = OperationCPUTimer::get(opCtx); - if (_metrics.cpuTimer) { + // The OperationCPUTimers may be nullptr on unsupported systems. + if (auto timers = OperationCPUTimers::get(opCtx)) { + _metrics.cpuTimer = timers->makeTimer(); _metrics.cpuTimer->start(); } } diff --git a/src/mongo/db/stats/resource_consumption_metrics.h b/src/mongo/db/stats/resource_consumption_metrics.h index f41042b29ab..59dffb7d2c3 100644 --- a/src/mongo/db/stats/resource_consumption_metrics.h +++ b/src/mongo/db/stats/resource_consumption_metrics.h @@ -230,7 +230,7 @@ public: WriteMetrics writeMetrics; // Records CPU time consumed by this operation. - OperationCPUTimer* cpuTimer = nullptr; + std::unique_ptr<OperationCPUTimer> cpuTimer; }; /** @@ -335,11 +335,6 @@ public: return _metrics; } - void reset() { - invariant(!isInScope()); - *this = {}; - } - /** * This should be called once per document read with the number of bytes read for that * document. This is a no-op when metrics collection is disabled on this operation. diff --git a/src/mongo/db/stats/resource_consumption_metrics_test.cpp b/src/mongo/db/stats/resource_consumption_metrics_test.cpp index 9c992bca916..cc980181a98 100644 --- a/src/mongo/db/stats/resource_consumption_metrics_test.cpp +++ b/src/mongo/db/stats/resource_consumption_metrics_test.cpp @@ -57,6 +57,11 @@ public: repl::ReplicationCoordinator::set(svcCtx, std::move(replCoord)); } + void reset(ResourceConsumption::MetricsCollector& metrics) { + metrics.~MetricsCollector(); + ::new (&metrics) ResourceConsumption::MetricsCollector(); + } + typedef std::pair<ServiceContext::UniqueClient, ServiceContext::UniqueOperationContext> ClientAndCtx; @@ -171,7 +176,7 @@ TEST_F(ResourceConsumptionMetricsTest, NestedScopedMetricsCollector) { ASSERT_EQ(metricsCopy.count("db2"), 0); ASSERT_EQ(metricsCopy.count("db3"), 0); - operationMetrics.reset(); + reset(operationMetrics); // Don't collect, nesting does not override that behavior. { @@ -244,7 +249,7 @@ TEST_F(ResourceConsumptionMetricsTest, IncrementReadMetrics) { ASSERT_EQ(metricsCopy["db1"].primaryReadMetrics.cursorSeeks, 1); // Clear metrics so we do not double-count. - operationMetrics.reset(); + reset(operationMetrics); { ResourceConsumption::ScopedMetricsCollector scope(_opCtx.get(), "db1"); @@ -299,7 +304,7 @@ TEST_F(ResourceConsumptionMetricsTest, IncrementReadMetricsSecondary) { ASSERT_EQ(metricsCopy["db1"].secondaryReadMetrics.cursorSeeks, 1); // Clear metrics so we do not double-count. - operationMetrics.reset(); + reset(operationMetrics); { ResourceConsumption::ScopedMetricsCollector scope(_opCtx.get(), "db1"); @@ -370,7 +375,7 @@ TEST_F(ResourceConsumptionMetricsTest, IncrementReadMetricsAcrossStates) { ASSERT_EQ(metricsCopy["db1"].secondaryReadMetrics.docsReturned.units(), 1 + 8); ASSERT_EQ(metricsCopy["db1"].secondaryReadMetrics.cursorSeeks, 1 + 1); - operationMetrics.reset(); + reset(operationMetrics); // Start collecting metrics in the secondary state, then change to primary. Metrics should be // attributed to the primary state only. @@ -650,7 +655,7 @@ TEST_F(ResourceConsumptionMetricsTest, CpuNanos) { auto& operationMetrics = ResourceConsumption::MetricsCollector::get(_opCtx.get()); // Do not run the test if a CPU timer is not available for this system. - if (!OperationCPUTimer::get(_opCtx.get())) { + if (!OperationCPUTimers::get(_opCtx.get())) { return; } diff --git a/src/mongo/s/query/results_merger_test_fixture.cpp b/src/mongo/s/query/results_merger_test_fixture.cpp index 637c879e87b..fe256d7e025 100644 --- a/src/mongo/s/query/results_merger_test_fixture.cpp +++ b/src/mongo/s/query/results_merger_test_fixture.cpp @@ -76,7 +76,7 @@ void ResultsMergerTestFixture::setUp() { setupShards(shards); - CurOp::get(operationContext())->ensureStarted(); + CurOp::get(operationContext())->ensureStarted(operationContext()); } } // namespace mongo diff --git a/src/mongo/s/service_entry_point_mongos.cpp b/src/mongo/s/service_entry_point_mongos.cpp index 47d6054c270..39f3f12e1b4 100644 --- a/src/mongo/s/service_entry_point_mongos.cpp +++ b/src/mongo/s/service_entry_point_mongos.cpp @@ -124,7 +124,7 @@ void HandleRequest::setupEnvironment() { NotPrimaryErrorTracker::get(client).startRequest(); AuthorizationSession::get(client)->startRequest(opCtx); - CurOp::get(opCtx)->ensureStarted(); + CurOp::get(opCtx)->ensureStarted(opCtx); } struct HandleRequest::CommandOpRunner { |