summaryrefslogtreecommitdiff
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
parent188549516c293b65c2c3cba5ae05a573b2eab460 (diff)
downloadmongo-d72f39af21ee012d54c0f49245790bc6d9119b6d.tar.gz
SERVER-70032 Report CPU time in slow query logs and profiler as cpuNanos
-rw-r--r--jstests/core/administrative/profile/profile_agg.js8
-rw-r--r--jstests/core/administrative/profile/profile_count.js8
-rw-r--r--jstests/core/administrative/profile/profile_delete.js7
-rw-r--r--jstests/core/administrative/profile/profile_distinct.js8
-rw-r--r--jstests/core/administrative/profile/profile_find.js8
-rw-r--r--jstests/core/administrative/profile/profile_findandmodify.js7
-rw-r--r--jstests/core/administrative/profile/profile_getmore.js8
-rw-r--r--jstests/core/administrative/profile/profile_insert.js9
-rw-r--r--jstests/core/administrative/profile/profile_mapreduce.js8
-rw-r--r--jstests/libs/os_helpers.js4
-rw-r--r--jstests/noPassthrough/aggregate_operation_metrics.js9
-rw-r--r--jstests/noPassthrough/profile_operation_metrics.js5
-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
40 files changed, 370 insertions, 134 deletions
diff --git a/jstests/core/administrative/profile/profile_agg.js b/jstests/core/administrative/profile/profile_agg.js
index c3a163ad81e..47f1a6d2c03 100644
--- a/jstests/core/administrative/profile/profile_agg.js
+++ b/jstests/core/administrative/profile/profile_agg.js
@@ -2,6 +2,7 @@
// @tags: [
// not_allowed_with_security_token,
// does_not_support_stepdowns,
+// requires_fcv_63,
// requires_profiling,
// ]
@@ -10,8 +11,8 @@
(function() {
"use strict";
-// For 'getLatestProfilerEntry()'.
-load("jstests/libs/profiler.js");
+load("jstests/libs/os_helpers.js"); // For isLinux().
+load("jstests/libs/profiler.js"); // For 'getLatestProfilerEntry()'.
const testDB = db.getSiblingDB("profile_agg");
assert.commandWorked(testDB.dropDatabase());
@@ -44,6 +45,9 @@ assert.eq(profileObj.command.aggregate, coll.getName(), tojson(profileObj));
assert.eq(profileObj.command.collation, {locale: "fr"}, tojson(profileObj));
assert.eq(profileObj.command.comment, "agg_comment", tojson(profileObj));
assert(profileObj.hasOwnProperty("responseLength"), tojson(profileObj));
+if (isLinux()) {
+ assert(profileObj.hasOwnProperty("cpuNanos"), tojson(profileObj));
+}
assert(profileObj.hasOwnProperty("millis"), tojson(profileObj));
assert(profileObj.hasOwnProperty("numYield"), tojson(profileObj));
assert(profileObj.hasOwnProperty("locks"), tojson(profileObj));
diff --git a/jstests/core/administrative/profile/profile_count.js b/jstests/core/administrative/profile/profile_count.js
index 02a581948c6..ebd14f50f44 100644
--- a/jstests/core/administrative/profile/profile_count.js
+++ b/jstests/core/administrative/profile/profile_count.js
@@ -3,6 +3,7 @@
// not_allowed_with_security_token,
// does_not_support_stepdowns,
// requires_fastcount,
+// requires_fcv_63,
// requires_profiling,
// ]
@@ -11,8 +12,8 @@
(function() {
"use strict";
-// For 'getLatestProfilerEntry()'.
-load("jstests/libs/profiler.js");
+load("jstests/libs/os_helpers.js"); // For isLinux().
+load("jstests/libs/profiler.js"); // For 'getLatestProfilerEntry()'.
var testDB = db.getSiblingDB("profile_count");
assert.commandWorked(testDB.dropDatabase());
@@ -41,6 +42,9 @@ assert.eq(profileObj.command.collation, {locale: "fr"}, tojson(profileObj));
assert.eq(profileObj.planSummary, "RECORD_STORE_FAST_COUNT", tojson(profileObj));
assert(profileObj.execStats.hasOwnProperty("stage"), tojson(profileObj));
assert(profileObj.hasOwnProperty("responseLength"), tojson(profileObj));
+if (isLinux()) {
+ assert(profileObj.hasOwnProperty("cpuNanos"), tojson(profileObj));
+}
assert(profileObj.hasOwnProperty("millis"), tojson(profileObj));
assert(profileObj.hasOwnProperty("numYield"), tojson(profileObj));
assert(profileObj.hasOwnProperty("locks"), tojson(profileObj));
diff --git a/jstests/core/administrative/profile/profile_delete.js b/jstests/core/administrative/profile/profile_delete.js
index e10f820ce03..1ae768153a6 100644
--- a/jstests/core/administrative/profile/profile_delete.js
+++ b/jstests/core/administrative/profile/profile_delete.js
@@ -4,6 +4,7 @@
// # Asserts on the number of index keys deleted.
// assumes_no_implicit_index_creation,
// does_not_support_stepdowns,
+// requires_fcv_63,
// requires_non_retryable_writes,
// requires_profiling,
// ]
@@ -14,7 +15,8 @@
"use strict";
load("jstests/libs/clustered_collections/clustered_collection_util.js");
-load("jstests/libs/profiler.js"); // For getLatestProfilerEntry.
+load("jstests/libs/os_helpers.js"); // For isLinux().
+load("jstests/libs/profiler.js"); // For getLatestProfilerEntry.
// Setup test db and collection.
var testDB = db.getSiblingDB("profile_delete");
@@ -50,6 +52,9 @@ assert.eq(profileObj.docsExamined, 1, tojson(profileObj));
assert.eq(profileObj.keysDeleted, expectedKeysDeleted, tojson(profileObj));
assert.eq(profileObj.planSummary, "IXSCAN { a: 1 }", tojson(profileObj));
assert(profileObj.execStats.hasOwnProperty("stage"), tojson(profileObj));
+if (isLinux()) {
+ assert(profileObj.hasOwnProperty("cpuNanos"), tojson(profileObj));
+}
assert(profileObj.hasOwnProperty("millis"), tojson(profileObj));
assert(profileObj.hasOwnProperty("numYield"), tojson(profileObj));
assert(profileObj.hasOwnProperty("locks"), tojson(profileObj));
diff --git a/jstests/core/administrative/profile/profile_distinct.js b/jstests/core/administrative/profile/profile_distinct.js
index 86eaf488286..5f96370c5a6 100644
--- a/jstests/core/administrative/profile/profile_distinct.js
+++ b/jstests/core/administrative/profile/profile_distinct.js
@@ -2,6 +2,7 @@
// @tags: [
// not_allowed_with_security_token,
// does_not_support_stepdowns,
+// requires_fcv_63,
// requires_profiling,
// ]
@@ -10,8 +11,8 @@
(function() {
"use strict";
-// For 'getLatestProfilerEntry()'.
-load("jstests/libs/profiler.js");
+load("jstests/libs/os_helpers.js"); // For isLinux().
+load("jstests/libs/profiler.js"); // For 'getLatestProfilerEntry()'.
var testDB = db.getSiblingDB("profile_distinct");
assert.commandWorked(testDB.dropDatabase());
@@ -42,6 +43,9 @@ assert.eq(profileObj.protocol, "op_msg", tojson(profileObj));
assert.eq(coll.getName(), profileObj.command.distinct, tojson(profileObj));
assert.eq(profileObj.command.collation, {locale: "fr"}, tojson(profileObj));
assert(profileObj.hasOwnProperty("responseLength"), tojson(profileObj));
+if (isLinux()) {
+ assert(profileObj.hasOwnProperty("cpuNanos"), tojson(profileObj));
+}
assert(profileObj.hasOwnProperty("millis"), tojson(profileObj));
assert(profileObj.hasOwnProperty("numYield"), tojson(profileObj));
assert(profileObj.hasOwnProperty("locks"), tojson(profileObj));
diff --git a/jstests/core/administrative/profile/profile_find.js b/jstests/core/administrative/profile/profile_find.js
index 4fae247a2bd..6066d0f987a 100644
--- a/jstests/core/administrative/profile/profile_find.js
+++ b/jstests/core/administrative/profile/profile_find.js
@@ -2,6 +2,7 @@
// @tags: [
// not_allowed_with_security_token,
// does_not_support_stepdowns,
+// requires_fcv_63,
// requires_profiling,
// ]
@@ -10,8 +11,8 @@
(function() {
"use strict";
-// For 'getLatestProfilerEntry()'.
-load("jstests/libs/profiler.js");
+load("jstests/libs/os_helpers.js"); // For isLinux().
+load("jstests/libs/profiler.js"); // For 'getLatestProfilerEntry()'.
var testDB = db.getSiblingDB("profile_find");
assert.commandWorked(testDB.dropDatabase());
@@ -49,6 +50,9 @@ assert.eq(profileObj.command.collation, {locale: "fr"});
assert.eq(profileObj.cursorExhausted, true, profileObj);
assert(!profileObj.hasOwnProperty("cursorid"), profileObj);
assert(profileObj.hasOwnProperty("responseLength"), profileObj);
+if (isLinux()) {
+ assert(profileObj.hasOwnProperty("cpuNanos"), tojson(profileObj));
+}
assert(profileObj.hasOwnProperty("millis"), profileObj);
assert(profileObj.hasOwnProperty("numYield"), profileObj);
assert(profileObj.hasOwnProperty("locks"), profileObj);
diff --git a/jstests/core/administrative/profile/profile_findandmodify.js b/jstests/core/administrative/profile/profile_findandmodify.js
index 1ba5a5dc885..7310cd96fbc 100644
--- a/jstests/core/administrative/profile/profile_findandmodify.js
+++ b/jstests/core/administrative/profile/profile_findandmodify.js
@@ -4,6 +4,7 @@
// not_allowed_with_security_token,
// # Asserts on the number of index keys modified.
// assumes_no_implicit_index_creation,
+// requires_fcv_63,
// requires_profiling,
// ]
@@ -11,7 +12,8 @@
"use strict";
load("jstests/libs/clustered_collections/clustered_collection_util.js");
-load("jstests/libs/profiler.js"); // For getLatestProfilerEntry.
+load("jstests/libs/os_helpers.js"); // For isLinux().
+load("jstests/libs/profiler.js"); // For getLatestProfilerEntry.
var testDB = db.getSiblingDB("profile_findandmodify");
assert.commandWorked(testDB.dropDatabase());
@@ -53,6 +55,9 @@ assert.eq(profileObj.planSummary, "COLLSCAN", tojson(profileObj));
assert(profileObj.execStats.hasOwnProperty("stage"), tojson(profileObj));
assert(profileObj.hasOwnProperty("numYield"), tojson(profileObj));
assert(profileObj.hasOwnProperty("responseLength"), tojson(profileObj));
+if (isLinux()) {
+ assert(profileObj.hasOwnProperty("cpuNanos"), tojson(profileObj));
+}
assert.eq(profileObj.appName, "MongoDB Shell", tojson(profileObj));
//
diff --git a/jstests/core/administrative/profile/profile_getmore.js b/jstests/core/administrative/profile/profile_getmore.js
index eb2a2428e21..78e3265c386 100644
--- a/jstests/core/administrative/profile/profile_getmore.js
+++ b/jstests/core/administrative/profile/profile_getmore.js
@@ -3,8 +3,8 @@
// not_allowed_with_security_token,
// does_not_support_stepdowns,
// requires_getmore,
+// requires_fcv_63,
// requires_profiling,
-// requires_fcv_51,
// ]
// Confirms that profiled getMore execution contains all expected metrics with proper values.
@@ -12,7 +12,8 @@
(function() {
"use strict";
-load("jstests/libs/profiler.js"); // For getLatestProfilerEntry.
+load("jstests/libs/os_helpers.js"); // For isLinux().
+load("jstests/libs/profiler.js"); // For getLatestProfilerEntry.
const testDB = db.getSiblingDB("profile_getmore");
assert.commandWorked(testDB.dropDatabase());
@@ -54,6 +55,9 @@ assert.eq(profileObj.planSummary, "IXSCAN { a: 1 }", profileObj);
assert(profileObj.hasOwnProperty("execStats"), profileObj);
assert(profileObj.execStats.hasOwnProperty("stage"), profileObj);
assert(profileObj.hasOwnProperty("responseLength"), profileObj);
+if (isLinux()) {
+ assert(profileObj.hasOwnProperty("cpuNanos"), tojson(profileObj));
+}
assert(profileObj.hasOwnProperty("numYield"), profileObj);
assert(profileObj.hasOwnProperty("locks"), profileObj);
assert(profileObj.locks.hasOwnProperty("Global"), profileObj);
diff --git a/jstests/core/administrative/profile/profile_insert.js b/jstests/core/administrative/profile/profile_insert.js
index 83cc920e200..8a07bbff252 100644
--- a/jstests/core/administrative/profile/profile_insert.js
+++ b/jstests/core/administrative/profile/profile_insert.js
@@ -7,15 +7,16 @@
// assumes_no_implicit_index_creation,
// assumes_write_concern_unchanged,
// does_not_support_stepdowns,
+// requires_fcv_63,
// requires_profiling,
// ]
(function() {
"use strict";
-// For 'getLatestProfilerEntry()'.
load("jstests/libs/clustered_collections/clustered_collection_util.js");
-load("jstests/libs/profiler.js");
+load("jstests/libs/os_helpers.js"); // For isLinux().
+load("jstests/libs/profiler.js"); // For 'getLatestProfilerEntry()'.
var testDB = db.getSiblingDB("profile_insert");
assert.commandWorked(testDB.dropDatabase());
@@ -42,7 +43,9 @@ assert.eq(profileObj.keysInserted, expectedKeysInserted, tojson(profileObj));
assert.eq(profileObj.command.ordered, true, tojson(profileObj));
assert.eq(profileObj.protocol, "op_msg", tojson(profileObj));
assert(profileObj.hasOwnProperty("responseLength"), tojson(profileObj));
-
+if (isLinux()) {
+ assert(profileObj.hasOwnProperty("cpuNanos"), tojson(profileObj));
+}
assert(profileObj.hasOwnProperty("numYield"), tojson(profileObj));
assert(profileObj.hasOwnProperty("locks"), tojson(profileObj));
assert(profileObj.hasOwnProperty("millis"), tojson(profileObj));
diff --git a/jstests/core/administrative/profile/profile_mapreduce.js b/jstests/core/administrative/profile/profile_mapreduce.js
index ddad8e50137..db60bfc0d66 100644
--- a/jstests/core/administrative/profile/profile_mapreduce.js
+++ b/jstests/core/administrative/profile/profile_mapreduce.js
@@ -5,6 +5,7 @@
// # mapReduce does not support afterClusterTime.
// does_not_support_causal_consistency,
// does_not_support_stepdowns,
+// requires_fcv_63,
// requires_profiling,
// uses_map_reduce_with_temp_collections,
// ]
@@ -14,8 +15,8 @@
(function() {
"use strict";
-// For 'getLatestProfilerEntry()'.
-load("jstests/libs/profiler.js");
+load("jstests/libs/os_helpers.js"); // For isLinux().
+load("jstests/libs/profiler.js"); // For 'getLatestProfilerEntry()'.
const testDB = db.getSiblingDB("profile_mapreduce");
assert.commandWorked(testDB.dropDatabase());
@@ -55,6 +56,9 @@ assert.eq(profileObj.protocol, "op_msg", tojson(profileObj));
assert.eq(coll.getName(), profileObj.command.mapreduce, tojson(profileObj));
assert.eq({locale: "fr"}, profileObj.command.collation, tojson(profileObj));
assert(profileObj.hasOwnProperty("responseLength"), tojson(profileObj));
+if (isLinux()) {
+ assert(profileObj.hasOwnProperty("cpuNanos"), tojson(profileObj));
+}
assert(profileObj.hasOwnProperty("millis"), tojson(profileObj));
assert(profileObj.hasOwnProperty("numYield"), tojson(profileObj));
assert(profileObj.hasOwnProperty("locks"), tojson(profileObj));
diff --git a/jstests/libs/os_helpers.js b/jstests/libs/os_helpers.js
index b700ee672f7..60a52a31ecc 100644
--- a/jstests/libs/os_helpers.js
+++ b/jstests/libs/os_helpers.js
@@ -2,6 +2,10 @@
* Test helpers for identifying OS
*/
+function isLinux() {
+ return getBuildInfo().buildEnvironment.target_os == "linux";
+}
+
function isRHEL8() {
if (_isWindows()) {
return false;
diff --git a/jstests/noPassthrough/aggregate_operation_metrics.js b/jstests/noPassthrough/aggregate_operation_metrics.js
index 10f3ebdc8ce..84d1ddff544 100644
--- a/jstests/noPassthrough/aggregate_operation_metrics.js
+++ b/jstests/noPassthrough/aggregate_operation_metrics.js
@@ -1,12 +1,15 @@
/**
* Tests command output from the $operationMetrics aggregation stage.
* @tags: [
+ * requires_fcv_63,
* requires_replication,
* ]
*/
(function() {
'use strict';
+load("jstests/libs/os_helpers.js"); // For isLinux().
+
var rst = new ReplSetTest({
nodes: 2,
nodeOptions: {setParameter: {"aggregateOperationResourceConsumptionMetrics": true}}
@@ -14,8 +17,6 @@ var rst = new ReplSetTest({
rst.startSet();
rst.initiate();
-const isLinux = getBuildInfo().buildEnvironment.target_os == "linux";
-
let assertMetricsExist = function(metrics) {
try {
assert.neq(metrics, undefined);
@@ -163,7 +164,7 @@ const secondary = rst.getSecondary();
}
// CPU time aggregation is only supported on Linux.
- if (isLinux) {
+ if (isLinux()) {
// Ensure the CPU time is increasing.
let lastCpuTime = getServerStatusMetrics(adminDB).cpuNanos;
assert.gt(lastCpuTime, initialCpuTime);
@@ -228,7 +229,7 @@ const secondary = rst.getSecondary();
ssMetrics = getServerStatusMetrics(adminDB);
assert.eq(0, ssMetrics.numMetrics);
assert.eq(0, ssMetrics.memUsage);
- if (isLinux) {
+ if (isLinux()) {
assert.neq(0, ssMetrics.cpuNanos);
} else {
assert.eq(0, ssMetrics.cpuNanos);
diff --git a/jstests/noPassthrough/profile_operation_metrics.js b/jstests/noPassthrough/profile_operation_metrics.js
index 11775313c42..63f3ded2142 100644
--- a/jstests/noPassthrough/profile_operation_metrics.js
+++ b/jstests/noPassthrough/profile_operation_metrics.js
@@ -3,6 +3,7 @@
*
* @tags: [
* requires_capped,
+ * requires_fcv_63,
* requires_replication,
* requires_wiredtiger,
* # TODO SERVER-71170: docBytesRead for read operations using cqf are reported are higher than
@@ -15,12 +16,12 @@
load("jstests/core/timeseries/libs/timeseries.js"); // For 'TimeseriesTest'.
load("jstests/libs/fixture_helpers.js"); // For isReplSet().
+load("jstests/libs/os_helpers.js"); // For isLinux().
load("jstests/libs/sbe_util.js"); // For checkSBEEnabled().
const dbName = jsTestName();
const collName = 'coll';
-const isLinux = getBuildInfo().buildEnvironment.target_os == "linux";
const isDebugBuild = (db) => {
return db.adminCommand('buildInfo').debug;
};
@@ -43,7 +44,7 @@ const assertMetricsExist = (profilerEntry) => {
// the OS may occasionally return the same CPU time between two different reads of the timer,
// resulting in the server calculating zero elapsed time.
// The CPU time metrics are only collected on Linux.
- if (isLinux) {
+ if (isLinux()) {
assert.gte(metrics.cpuNanos, 0);
}
assert.gte(metrics.docBytesWritten, 0);
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 {