summaryrefslogtreecommitdiff
path: root/src
diff options
context:
space:
mode:
authorLouis Williams <louis.williams@mongodb.com>2023-02-10 08:11:54 +0000
committerEvergreen Agent <no-reply@evergreen.mongodb.com>2023-02-10 09:39:12 +0000
commitd72f39af21ee012d54c0f49245790bc6d9119b6d (patch)
tree9eb64267ee2cbe5dcce81a15672a5e0752ec2df6 /src
parent188549516c293b65c2c3cba5ae05a573b2eab460 (diff)
downloadmongo-d72f39af21ee012d54c0f49245790bc6d9119b6d.tar.gz
SERVER-70032 Report CPU time in slow query logs and profiler as cpuNanos
Diffstat (limited to 'src')
-rw-r--r--src/mongo/db/catalog/drop_database.cpp3
-rw-r--r--src/mongo/db/client.cpp8
-rw-r--r--src/mongo/db/commands/dbcommands.cpp8
-rw-r--r--src/mongo/db/commands/find_and_modify.cpp8
-rw-r--r--src/mongo/db/curop.cpp52
-rw-r--r--src/mongo/db/curop.h19
-rw-r--r--src/mongo/db/curop_test.cpp2
-rw-r--r--src/mongo/db/db_raii.cpp6
-rw-r--r--src/mongo/db/db_raii_test.cpp2
-rw-r--r--src/mongo/db/index_builds_coordinator.cpp4
-rw-r--r--src/mongo/db/operation_cpu_timer.cpp68
-rw-r--r--src/mongo/db/operation_cpu_timer.h55
-rw-r--r--src/mongo/db/operation_cpu_timer_test.cpp117
-rw-r--r--src/mongo/db/ops/write_ops_exec.cpp8
-rw-r--r--src/mongo/db/pipeline/document_source_merge_cursors_test.cpp2
-rw-r--r--src/mongo/db/repl/replication_coordinator_impl.cpp2
-rw-r--r--src/mongo/db/s/config/initial_split_policy.cpp2
-rw-r--r--src/mongo/db/s/global_index/global_index_cloner_fetcher.cpp2
-rw-r--r--src/mongo/db/s/periodic_sharded_index_consistency_checker.cpp2
-rw-r--r--src/mongo/db/s/resharding/resharding_collection_cloner.cpp2
-rw-r--r--src/mongo/db/s/resharding/resharding_data_copy_util.cpp5
-rw-r--r--src/mongo/db/s/resharding/resharding_txn_cloner.cpp2
-rw-r--r--src/mongo/db/service_entry_point_common.cpp4
-rw-r--r--src/mongo/db/stats/resource_consumption_metrics.cpp6
-rw-r--r--src/mongo/db/stats/resource_consumption_metrics.h7
-rw-r--r--src/mongo/db/stats/resource_consumption_metrics_test.cpp15
-rw-r--r--src/mongo/s/query/results_merger_test_fixture.cpp2
-rw-r--r--src/mongo/s/service_entry_point_mongos.cpp2
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 {