From 0d5ad158ceb6fea1004034bcb78c82c9daf69eac Mon Sep 17 00:00:00 2001 From: Louis Williams Date: Fri, 27 Jan 2023 09:30:25 +0000 Subject: SERVER-70032 Report CPU time in slow query logs and profiler as cpuNanos --- jstests/core/administrative/profile/profile_agg.js | 8 +- .../core/administrative/profile/profile_count.js | 8 +- .../core/administrative/profile/profile_delete.js | 7 +- .../administrative/profile/profile_distinct.js | 8 +- .../core/administrative/profile/profile_find.js | 8 +- .../profile/profile_findandmodify.js | 7 +- .../core/administrative/profile/profile_getmore.js | 8 +- .../core/administrative/profile/profile_insert.js | 9 +- .../administrative/profile/profile_mapreduce.js | 8 +- jstests/libs/os_helpers.js | 4 + .../noPassthrough/aggregate_operation_metrics.js | 9 +- jstests/noPassthrough/profile_operation_metrics.js | 5 +- src/mongo/db/catalog/drop_database.cpp | 3 +- src/mongo/db/client.cpp | 8 +- src/mongo/db/commands/dbcommands.cpp | 8 +- src/mongo/db/commands/find_and_modify.cpp | 8 +- src/mongo/db/commands/write_commands.cpp | 2 +- src/mongo/db/curop.cpp | 52 +++++----- src/mongo/db/curop.h | 19 +++- src/mongo/db/curop_test.cpp | 2 +- src/mongo/db/db_raii.cpp | 6 +- src/mongo/db/db_raii_test.cpp | 2 +- src/mongo/db/index_builds_coordinator.cpp | 4 +- src/mongo/db/operation_cpu_timer.cpp | 56 +++++++++-- src/mongo/db/operation_cpu_timer.h | 45 ++++++++- src/mongo/db/operation_cpu_timer_test.cpp | 106 ++++++++++++++++----- src/mongo/db/ops/write_ops_exec.cpp | 6 +- .../document_source_merge_cursors_test.cpp | 2 +- src/mongo/db/repl/replication_coordinator_impl.cpp | 2 +- src/mongo/db/s/config/initial_split_policy.cpp | 2 +- .../s/global_index/global_index_cloner_fetcher.cpp | 2 +- .../periodic_sharded_index_consistency_checker.cpp | 2 +- .../s/resharding/resharding_collection_cloner.cpp | 2 +- .../db/s/resharding/resharding_data_copy_util.cpp | 5 +- .../db/s/resharding/resharding_txn_cloner.cpp | 2 +- src/mongo/db/service_entry_point_common.cpp | 4 +- .../db/stats/resource_consumption_metrics.cpp | 6 +- src/mongo/db/stats/resource_consumption_metrics.h | 7 +- .../db/stats/resource_consumption_metrics_test.cpp | 15 ++- src/mongo/s/query/results_merger_test_fixture.cpp | 2 +- src/mongo/s/service_entry_point_mongos.cpp | 2 +- 41 files changed, 337 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 0744555ed3b..f969037948c 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,11 +16,11 @@ 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(). const dbName = jsTestName(); const collName = 'coll'; -const isLinux = getBuildInfo().buildEnvironment.target_os == "linux"; const isDebugBuild = (db) => { return db.adminCommand('buildInfo').debug; }; @@ -48,7 +49,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 4125964f27d..7d4b2f73a8c 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 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 lk(*opCtx->getClient()); CurOp::get(opCtx)->setNS_inlock(dbname); } @@ -676,9 +675,10 @@ public: } else { { stdx::lock_guard 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 ada72bfe8c2..2845cac71ca 100644 --- a/src/mongo/db/commands/find_and_modify.cpp +++ b/src/mongo/db/commands/find_and_modify.cpp @@ -367,7 +367,9 @@ write_ops::FindAndModifyCommandReply CmdFindAndModify::Invocation::writeConflict { stdx::lock_guard 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); @@ -431,7 +433,9 @@ write_ops::FindAndModifyCommandReply CmdFindAndModify::Invocation::writeConflict { stdx::lock_guard 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/commands/write_commands.cpp b/src/mongo/db/commands/write_commands.cpp index ff76beaad3b..1e30a80c09c 100644 --- a/src/mongo/db/commands/write_commands.cpp +++ b/src/mongo/db/commands/write_commands.cpp @@ -1516,7 +1516,7 @@ public: stdx::lock_guard lk(*opCtx->getClient()); curOp.setNS_inlock(ns()); curOp.setLogicalOp_inlock(LogicalOp::opInsert); - curOp.ensureStarted(); + curOp.ensureStarted(opCtx); curOp.debug().additiveMetrics.ninserted = 0; } diff --git a/src/mongo/db/curop.cpp b/src/mongo/db/curop.cpp index a34985919d0..fceff05d7cb 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; @@ -362,21 +358,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 @@ -387,12 +380,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, @@ -407,14 +399,14 @@ Microseconds CurOp::computeElapsedTimeTotal(TickSource::Tick startTime, return _tickSource->ticksTo(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) { @@ -1007,6 +999,10 @@ void OpDebug::report(OperationContext* opCtx, pAttrs->add("operationMetrics", builder.obj()); } + if (cpuTime > Nanoseconds::zero()) { + pAttrs->add("cpuNanos", durationCount(cpuTime)); + } + if (client && client->session()) { pAttrs->add("remote", client->session()->remote()); } @@ -1188,6 +1184,10 @@ void OpDebug::append(OperationContext* opCtx, b.append("remoteOpWaitMillis", durationCount(*remoteOpWaitTime)); } + if (cpuTime > Nanoseconds::zero()) { + b.appendNumber("cpuNanos", durationCount(cpuTime)); + } + b.appendNumber("millis", durationCount(executionTime)); if (!curop.getPlanSummary().empty()) { @@ -1493,6 +1493,12 @@ std::function OpDebug::appendStaged(StringSet requ } }); + addIfNeeded("cpuNanos", [](auto field, auto args, auto& b) { + if (args.op.cpuTime > Nanoseconds::zero()) { + b.appendNumber(field, durationCount(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 9205c16bf46..f3d73b8c8d3 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}; @@ -451,8 +456,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. @@ -573,8 +578,8 @@ public: // negative, if the system time has been reset during the course of this operation. // - void ensureStarted() { - static_cast(startTime()); + void ensureStarted(OperationContext* opCtx) { + static_cast(startTime(opCtx)); } bool isStarted() const { return _start.load() != 0; @@ -879,7 +884,7 @@ public: private: class CurOpStack; - TickSource::Tick startTime(); + TickSource::Tick startTime(OperationContext* opCtx); Microseconds computeElapsedTimeTotal(TickSource::Tick startTime, TickSource::Tick endTime) const; @@ -908,6 +913,10 @@ private: // The time at which this CurOp instance was marked as done or 0 if the CurOp is not yet done. std::atomic _end{0}; // NOLINT + // This CPU timer tracks the CPU time spent for this operation. Will be nullptr on unsupported + // platforms. + std::unique_ptr _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 fc9e05e37c4..3b7442dc2df 100644 --- a/src/mongo/db/curop_test.cpp +++ b/src/mongo/db/curop_test.cpp @@ -254,7 +254,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 3ebd98b0c9b..12b21813493 100644 --- a/src/mongo/db/db_raii.cpp +++ b/src/mongo/db/db_raii.cpp @@ -525,7 +525,7 @@ AutoStatsTracker::AutoStatsTracker( } stdx::lock_guard clientLock(*_opCtx->getClient()); - CurOp::get(_opCtx)->enter_inlock(nss, dbProfilingLevel); + CurOp::get(_opCtx)->enter_inlock(opCtx, nss, dbProfilingLevel); } AutoStatsTracker::~AutoStatsTracker() { @@ -1595,8 +1595,8 @@ OldClientContext::OldClientContext(OperationContext* opCtx, } stdx::lock_guard 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 776afdfa0aa..ee15f625411 100644 --- a/src/mongo/db/db_raii_test.cpp +++ b/src/mongo/db/db_raii_test.cpp @@ -74,7 +74,7 @@ std::unique_ptr 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 expCtx; diff --git a/src/mongo/db/index_builds_coordinator.cpp b/src/mongo/db/index_builds_coordinator.cpp index 9a52e7b8688..6b3e5195591 100644 --- a/src/mongo/db/index_builds_coordinator.cpp +++ b/src/mongo/db/index_builds_coordinator.cpp @@ -355,7 +355,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); } /** @@ -1907,7 +1907,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..1aab6bc8d2b 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(OperationCPUTimers* timers) : OperationCPUTimer(timers) {} + ~PosixTimer() = default; + Nanoseconds getElapsed() const override; void start() override; @@ -157,14 +160,12 @@ 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(); +// Set of timers created by this OperationContext. +static auto getCPUTimers = OperationContext::declareDecoration(); } // 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 +185,56 @@ OperationCPUTimer* OperationCPUTimer::get(OperationContext* opCtx) { if (!isTimeSupported) return nullptr; - return &getCPUTimer(opCtx); + + return &getCPUTimers(opCtx); +} + +std::unique_ptr OperationCPUTimers::makeTimer() { + return std::make_unique(this); } #else // not defined(__linux__) -OperationCPUTimer* OperationCPUTimer::get(OperationContext*) { +OperationCPUTimers* OperationCPUTimers::get(OperationContext*) { return nullptr; } +std::unique_ptr OperationCPUTimers::makeTimer() { + MONGO_UNREACHABLE; +} + #endif // defined(__linux__) +OperationCPUTimer::OperationCPUTimer(OperationCPUTimers* timers) : _timers(timers) { + _it = _timers->_add(this); +} + +OperationCPUTimer::~OperationCPUTimer() { + _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..8295a8f16b5 100644 --- a/src/mongo/db/operation_cpu_timer.h +++ b/src/mongo/db/operation_cpu_timer.h @@ -29,11 +29,43 @@ #pragma once +#include + #include "mongo/util/duration.h" namespace mongo { class OperationContext; +class OperationCPUTimer; + +/** + * Allocates and tracks CPU timers for an OperationContext. + */ +class OperationCPUTimers { +public: + friend class OperationCPUTimer; + + /** + * Returns `nullptr` if the platform does not support tracking of CPU consumption. + */ + static OperationCPUTimers* get(OperationContext*); + + std::unique_ptr makeTimer(); + + void onThreadAttach(); + void onThreadDetach(); + + size_t count() const; + +private: + using Iterator = std::list::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 _timers; +}; /** * Implements the CPU timer for platforms that support CPU consumption tracking. Consider the @@ -54,10 +86,8 @@ class OperationContext; */ class OperationCPUTimer { public: - /** - * Returns `nullptr` if the platform does not support tracking of CPU consumption. - */ - static OperationCPUTimer* get(OperationContext*); + OperationCPUTimer(OperationCPUTimers* timers); + virtual ~OperationCPUTimer(); virtual Nanoseconds getElapsed() const = 0; @@ -66,6 +96,13 @@ public: virtual void onThreadAttach() = 0; virtual void onThreadDetach() = 0; + +private: + // Reference to OperationContext-owned tracked list of timers. + 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..41d20eb22ac 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 makeTimer() const { + return getTimers()->makeTimer(); } void setUp() { @@ -80,7 +84,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 +98,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 +118,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 +135,96 @@ 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()); } 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 +243,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 +280,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 bd4084e0c32..0318f84390d 100644 --- a/src/mongo/db/ops/write_ops_exec.cpp +++ b/src/mongo/db/ops/write_ops_exec.cpp @@ -577,7 +577,7 @@ WriteResult performInserts(OperationContext* opCtx, stdx::lock_guard lk(*opCtx->getClient()); curOp.setNS_inlock(wholeOp.getNamespace()); curOp.setLogicalOp_inlock(LogicalOp::opInsert); - curOp.ensureStarted(); + curOp.ensureStarted(opCtx); curOp.debug().additiveMetrics.ninserted = 0; } @@ -879,7 +879,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, @@ -1078,7 +1078,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{}; 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 04bf762d340..df07390e1e6 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 getExpCtx() { diff --git a/src/mongo/db/repl/replication_coordinator_impl.cpp b/src/mongo/db/repl/replication_coordinator_impl.cpp index e6af5c08838..18859eb860c 100644 --- a/src/mongo/db/repl/replication_coordinator_impl.cpp +++ b/src/mongo/db/repl/replication_coordinator_impl.cpp @@ -4228,7 +4228,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 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 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 19ad0fdbbd4..55790700333 100644 --- a/src/mongo/db/s/resharding/resharding_data_copy_util.cpp +++ b/src/mongo/db/s/resharding/resharding_data_copy_util.cpp @@ -193,8 +193,9 @@ std::vector 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 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 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 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 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 33a1816d795..c3aa4d6e0ec 100644 --- a/src/mongo/s/query/results_merger_test_fixture.cpp +++ b/src/mongo/s/query/results_merger_test_fixture.cpp @@ -75,7 +75,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 { -- cgit v1.2.1