summaryrefslogtreecommitdiff
diff options
context:
space:
mode:
-rw-r--r--jstests/libs/analyze_plan.js12
-rw-r--r--jstests/noPassthrough/explain_execution_time_in_microseconds.js86
-rw-r--r--src/mongo/SConscript1
-rw-r--r--src/mongo/db/exec/SConscript2
-rw-r--r--src/mongo/db/exec/cached_plan.cpp5
-rw-r--r--src/mongo/db/exec/multi_plan.cpp5
-rw-r--r--src/mongo/db/exec/plan_stage.cpp5
-rw-r--r--src/mongo/db/exec/plan_stage.h15
-rw-r--r--src/mongo/db/exec/plan_stats.h10
-rw-r--r--src/mongo/db/exec/sbe/stages/plan_stats.cpp4
-rw-r--r--src/mongo/db/exec/sbe/stages/plan_stats.h7
-rw-r--r--src/mongo/db/exec/sbe/stages/stages.h19
-rw-r--r--src/mongo/db/exec/scoped_timer.cpp9
-rw-r--r--src/mongo/db/exec/scoped_timer.h24
-rw-r--r--src/mongo/db/exec/scoped_timer_factory.cpp50
-rw-r--r--src/mongo/db/exec/scoped_timer_factory.h47
-rw-r--r--src/mongo/db/exec/subplan.cpp4
-rw-r--r--src/mongo/db/pipeline/document_source.cpp2
-rw-r--r--src/mongo/db/pipeline/document_source.h8
-rw-r--r--src/mongo/db/pipeline/pipeline.cpp5
-rw-r--r--src/mongo/db/query/classic_plan_cache.cpp4
-rw-r--r--src/mongo/db/query/explain.cpp13
-rw-r--r--src/mongo/db/query/plan_explainer_impl.cpp10
-rw-r--r--src/mongo/db/query/plan_explainer_sbe.cpp15
-rw-r--r--src/mongo/db/query/plan_summary_stats.h14
-rw-r--r--src/mongo/db/query/query_knobs.idl8
-rw-r--r--src/mongo/db/service_context.cpp2
-rw-r--r--src/mongo/db/service_context.h20
-rw-r--r--src/mongo/util/clock_tick_source.cpp49
-rw-r--r--src/mongo/util/clock_tick_source.h60
-rw-r--r--src/mongo/util/tick_source_test.cpp23
31 files changed, 459 insertions, 79 deletions
diff --git a/jstests/libs/analyze_plan.js b/jstests/libs/analyze_plan.js
index 30c42907610..2bf3322fc71 100644
--- a/jstests/libs/analyze_plan.js
+++ b/jstests/libs/analyze_plan.js
@@ -38,12 +38,12 @@ function getCachedPlan(cachedPlan) {
/**
* Given the root stage of explain's JSON representation of a query plan ('root'), returns all
* subdocuments whose stage is 'stage'. Returns an empty array if the plan does not have the
- * requested stage.
+ * requested stage. if 'stage' is 'null' returns all the stages in 'root'.
*/
function getPlanStages(root, stage) {
var results = [];
- if (root.stage === stage) {
+ if (root.stage === stage || stage === undefined) {
results.push(root);
}
@@ -96,6 +96,14 @@ function getPlanStages(root, stage) {
}
/**
+ * Given the root stage of explain's JSON representation of a query plan ('root'), returns a list of
+ * all the stages in 'root'.
+ */
+function getAllPlanStages(root) {
+ return getPlanStages(root);
+}
+
+/**
* Given the root stage of explain's JSON representation of a query plan ('root'), returns the
* subdocument with its stage as 'stage'. Returns null if the plan does not have such a stage.
* Asserts that no more than one stage is a match.
diff --git a/jstests/noPassthrough/explain_execution_time_in_microseconds.js b/jstests/noPassthrough/explain_execution_time_in_microseconds.js
new file mode 100644
index 00000000000..2525aef8c3c
--- /dev/null
+++ b/jstests/noPassthrough/explain_execution_time_in_microseconds.js
@@ -0,0 +1,86 @@
+// When running explain commands with "executionStats" verbosity, checks that the explain output
+// includes "executionTimeMicros" only if requested. "executionTimeMillisEstimate" will
+// always be present in the explain output.
+(function() {
+"use strict";
+
+load("jstests/libs/analyze_plan.js"); // For getAllPlanStages().
+
+let conn = MongoRunner.runMongod({});
+assert.neq(conn, null, "mongod failed to start up");
+
+let db = conn.getDB("test");
+let coll = db.explain_execution_time_in_microseconds;
+coll.drop();
+
+assert.commandWorked(coll.createIndex({x: 1}));
+assert.commandWorked(coll.createIndex({y: 1}));
+
+for (let i = 0; i < 1000; i++) {
+ assert.commandWorked(coll.insert({x: i, y: i * 2}));
+}
+
+function verifyStages(execStages, microExpected) {
+ const allStages = getAllPlanStages(execStages);
+ assert.eq(execStages.hasOwnProperty("executionTimeMicros"), microExpected);
+ for (let stage of allStages) {
+ assert(stage.hasOwnProperty("executionTimeMillisEstimate"), stage);
+ assert.eq(stage.hasOwnProperty("executionTimeMicros"), microExpected, stage);
+ }
+}
+
+// Test explain on find command.
+let explainResult = coll.find({x: {$gt: 500}}).explain("executionStats");
+let executionStages = explainResult.executionStats.executionStages;
+assert(executionStages.hasOwnProperty("executionTimeMillisEstimate"), executionStages);
+verifyStages(executionStages, false);
+
+// Test explain on aggregate command.
+const pipeline = [{$match: {x: {$gt: 500}}}, {$addFields: {xx: {$add: ["$x", "$y"]}}}];
+// Run an explain command when the "executionTimeMicros" should be omitted.
+explainResult = coll.explain("executionStats").aggregate(pipeline);
+executionStages = explainResult.stages;
+assert.neq(executionStages.length, 0, executionStages);
+
+for (let executionStage of executionStages) {
+ // We should only have "executionTimeMillisEstimate" in the explain output.
+ assert(executionStage.hasOwnProperty("executionTimeMillisEstimate"), executionStage);
+ assert(!executionStage.hasOwnProperty("executionTimeMicros"), executionStage);
+ if (executionStage.hasOwnProperty("$cursor")) {
+ const stages = executionStage["$cursor"]["executionStats"]["executionStages"];
+ verifyStages(stages, false);
+ }
+}
+
+MongoRunner.stopMongod(conn);
+
+// Request microsecond precision for the estimates of execution time.
+conn =
+ MongoRunner.runMongod({setParameter: "internalMeasureQueryExecutionTimeInMicroseconds=true"});
+assert.neq(conn, null, "mongod failed to start up");
+db = conn.getDB("test");
+coll = db.explain_execution_time_in_microseconds;
+
+explainResult = coll.find({x: {$gt: 500}}).explain("executionStats");
+let isSBE = explainResult.explainVersion === "2";
+executionStages = explainResult.executionStats.executionStages;
+assert(executionStages.hasOwnProperty("executionTimeMillisEstimate"), executionStages);
+verifyStages(executionStages, isSBE);
+
+explainResult = coll.explain("executionStats").aggregate(pipeline);
+executionStages = explainResult.stages;
+isSBE = explainResult.explainVersion === "2";
+assert.neq(executionStages.length, 0, executionStages);
+for (let executionStage of executionStages) {
+ assert(executionStage.hasOwnProperty("executionTimeMillisEstimate"), executionStage);
+ // "executionTimeMicros" is only added to SBE stages, not to agg stages.
+ assert(!executionStage.hasOwnProperty("executionTimeMicros"), executionStage);
+
+ if (executionStage.hasOwnProperty("$cursor")) {
+ const stages = executionStage["$cursor"]["executionStats"]["executionStages"];
+ verifyStages(stages, isSBE);
+ }
+}
+
+MongoRunner.stopMongod(conn);
+})();
diff --git a/src/mongo/SConscript b/src/mongo/SConscript
index 9ef161c8bd6..b8bc357d941 100644
--- a/src/mongo/SConscript
+++ b/src/mongo/SConscript
@@ -193,6 +193,7 @@ baseEnv.Library(
'util/assert_util.cpp',
'util/base64.cpp',
'util/boost_assert_impl.cpp',
+ 'util/clock_tick_source.cpp',
'util/concurrency/idle_thread_block.cpp',
'util/concurrency/thread_name.cpp',
'util/duration.cpp',
diff --git a/src/mongo/db/exec/SConscript b/src/mongo/db/exec/SConscript
index 992201118d8..6c1c9548619 100644
--- a/src/mongo/db/exec/SConscript
+++ b/src/mongo/db/exec/SConscript
@@ -32,8 +32,10 @@ env.Library(
target="scoped_timer",
source=[
"scoped_timer.cpp",
+ "scoped_timer_factory.cpp",
],
LIBDEPS=[
+ '$BUILD_DIR/mongo/db/service_context',
'$BUILD_DIR/mongo/util/net/network',
],
)
diff --git a/src/mongo/db/exec/cached_plan.cpp b/src/mongo/db/exec/cached_plan.cpp
index 67d5da939d3..487431de5d8 100644
--- a/src/mongo/db/exec/cached_plan.cpp
+++ b/src/mongo/db/exec/cached_plan.cpp
@@ -77,9 +77,8 @@ CachedPlanStage::CachedPlanStage(ExpressionContext* expCtx,
}
Status CachedPlanStage::pickBestPlan(PlanYieldPolicy* yieldPolicy) {
- // Adds the amount of time taken by pickBestPlan() to executionTimeMillis. There's lots of
- // execution work that happens here, so this is needed for the time accounting to
- // make sense.
+ // Adds the amount of time taken by pickBestPlan() to executionTime. There's lots of execution
+ // work that happens here, so this is needed for the time accounting to make sense.
auto optTimer = getOptTimer();
// During plan selection, the list of indices we are using to plan must remain stable, so the
diff --git a/src/mongo/db/exec/multi_plan.cpp b/src/mongo/db/exec/multi_plan.cpp
index b7bd06ae024..60c3f018e25 100644
--- a/src/mongo/db/exec/multi_plan.cpp
+++ b/src/mongo/db/exec/multi_plan.cpp
@@ -195,9 +195,8 @@ void MultiPlanStage::tryYield(PlanYieldPolicy* yieldPolicy) {
}
Status MultiPlanStage::pickBestPlan(PlanYieldPolicy* yieldPolicy) {
- // Adds the amount of time taken by pickBestPlan() to executionTimeMillis. There's lots of
- // execution work that happens here, so this is needed for the time accounting to
- // make sense.
+ // Adds the amount of time taken by pickBestPlan() to executionTime. There's lots of execution
+ // work that happens here, so this is needed for the time accounting to make sense.
auto optTimer = getOptTimer();
auto tickSource = opCtx()->getServiceContext()->getTickSource();
diff --git a/src/mongo/db/exec/plan_stage.cpp b/src/mongo/db/exec/plan_stage.cpp
index fdff4638d17..4976b1efed0 100644
--- a/src/mongo/db/exec/plan_stage.cpp
+++ b/src/mongo/db/exec/plan_stage.cpp
@@ -78,9 +78,4 @@ void PlanStage::reattachToOperationContext(OperationContext* opCtx) {
doReattachToOperationContext();
}
-
-ClockSource* PlanStage::getClock() const {
- return _opCtx->getServiceContext()->getFastClockSource();
-}
-
} // namespace mongo
diff --git a/src/mongo/db/exec/plan_stage.h b/src/mongo/db/exec/plan_stage.h
index 418305a3c04..a5b894e529f 100644
--- a/src/mongo/db/exec/plan_stage.h
+++ b/src/mongo/db/exec/plan_stage.h
@@ -34,8 +34,10 @@
#include "mongo/db/exec/plan_stats.h"
#include "mongo/db/exec/scoped_timer.h"
+#include "mongo/db/exec/scoped_timer_factory.h"
#include "mongo/db/exec/working_set.h"
#include "mongo/db/pipeline/expression_context.h"
+#include "mongo/db/query/plan_summary_stats.h"
#include "mongo/db/query/restore_context.h"
namespace mongo {
@@ -116,7 +118,7 @@ public:
if (expCtx->explain || expCtx->mayDbProfile) {
// Populating the field for execution time indicates that this stage should time each
// call to work().
- _commonStats.executionTimeMillis.emplace(0);
+ _commonStats.executionTime.emplace(0);
}
}
@@ -346,8 +348,9 @@ public:
* execution has started.
*/
void markShouldCollectTimingInfo() {
- invariant(!_commonStats.executionTimeMillis || *_commonStats.executionTimeMillis == 0);
- _commonStats.executionTimeMillis.emplace(0);
+ invariant(!_commonStats.executionTime ||
+ durationCount<Microseconds>(*_commonStats.executionTime) == 0);
+ _commonStats.executionTime.emplace(0);
}
protected:
@@ -400,8 +403,10 @@ protected:
* stage. May return boost::none if it is not necessary to collect timing info.
*/
boost::optional<ScopedTimer> getOptTimer() {
- if (_commonStats.executionTimeMillis) {
- return {{getClock(), _commonStats.executionTimeMillis.get_ptr()}};
+ if (_opCtx && _commonStats.executionTime) {
+ return scoped_timer_factory::make(_opCtx->getServiceContext(),
+ QueryExecTimerPrecision::kMillis,
+ _commonStats.executionTime.get_ptr());
}
return boost::none;
diff --git a/src/mongo/db/exec/plan_stats.h b/src/mongo/db/exec/plan_stats.h
index e65934f19bc..6f621872985 100644
--- a/src/mongo/db/exec/plan_stats.h
+++ b/src/mongo/db/exec/plan_stats.h
@@ -104,15 +104,7 @@ struct CommonStats {
// The field must be populated when running explain or when running with the profiler on. It
// must also be populated when multi planning, in order to gather stats stored in the plan
// cache.
- boost::optional<long long> executionTimeMillis;
-
- // TODO: have some way of tracking WSM sizes (or really any series of #s). We can measure
- // the size of our inputs and the size of our outputs. We can do a lot with the WS here.
-
- // TODO: once we've picked a plan, collect different (or additional) stats for display to
- // the user, eg. time_t totalTimeSpent;
-
- // TODO: keep track of the total yield time / fetch time done for a plan.
+ boost::optional<Microseconds> executionTime;
bool failed;
bool isEOF;
diff --git a/src/mongo/db/exec/sbe/stages/plan_stats.cpp b/src/mongo/db/exec/sbe/stages/plan_stats.cpp
index c0ba82d3cd8..3fe032c60bc 100644
--- a/src/mongo/db/exec/sbe/stages/plan_stats.cpp
+++ b/src/mongo/db/exec/sbe/stages/plan_stats.cpp
@@ -50,9 +50,7 @@ PlanSummaryStats collectExecutionStatsSummary(const PlanStageStats& root) {
PlanSummaryStats summary;
summary.nReturned = root.common.advances;
- if (root.common.executionTimeMillis) {
- summary.executionTimeMillisEstimate = *root.common.executionTimeMillis;
- }
+ summary.executionTime = root.common.executionTime;
auto visitor = PlanSummaryStatsVisitor(summary);
auto walker = PlanStageStatsWalker<true, CommonStats>(nullptr, nullptr, &visitor);
diff --git a/src/mongo/db/exec/sbe/stages/plan_stats.h b/src/mongo/db/exec/sbe/stages/plan_stats.h
index 99798fc247a..c84ae2c83e2 100644
--- a/src/mongo/db/exec/sbe/stages/plan_stats.h
+++ b/src/mongo/db/exec/sbe/stages/plan_stats.h
@@ -53,13 +53,12 @@ struct CommonStats {
// PlanStages corresponds to an MQL operation specified by the user.
const PlanNodeId nodeId;
- // Time elapsed while working inside this stage. When this field is set to boost::none,
- // timing info will not be collected during query execution.
+ // Time elapsed while working inside this stage.
//
// The field must be populated when running explain or when running with the profiler on. It
// must also be populated when multi planning, in order to gather stats stored in the plan
- // cache.
- boost::optional<long long> executionTimeMillis;
+ // cache. This struct includes the execution time and its precision/unit.
+ QueryExecTime executionTime;
size_t advances{0};
size_t opens{0};
diff --git a/src/mongo/db/exec/sbe/stages/stages.h b/src/mongo/db/exec/sbe/stages/stages.h
index 02dd6ae62fb..f049f65fcc0 100644
--- a/src/mongo/db/exec/sbe/stages/stages.h
+++ b/src/mongo/db/exec/sbe/stages/stages.h
@@ -35,9 +35,11 @@
#include "mongo/db/exec/sbe/values/slot.h"
#include "mongo/db/exec/sbe/values/value.h"
#include "mongo/db/exec/scoped_timer.h"
+#include "mongo/db/exec/scoped_timer_factory.h"
#include "mongo/db/exec/trial_run_tracker.h"
#include "mongo/db/operation_context.h"
#include "mongo/db/query/plan_yield_policy.h"
+#include "mongo/db/query/query_knobs_gen.h"
#include "mongo/util/str.h"
namespace mongo {
@@ -356,8 +358,14 @@ public:
* execution has started.
*/
void markShouldCollectTimingInfo() {
- invariant(!_commonStats.executionTimeMillis || *_commonStats.executionTimeMillis == 0);
- _commonStats.executionTimeMillis.emplace(0);
+ invariant(durationCount<Microseconds>(_commonStats.executionTime.executionTimeEstimate) ==
+ 0);
+
+ if (internalMeasureQueryExecutionTimeInMicroseconds.load()) {
+ _commonStats.executionTime.precision = QueryExecTimerPrecision::kMicros;
+ } else {
+ _commonStats.executionTime.precision = QueryExecTimerPrecision::kMillis;
+ }
auto stage = static_cast<T*>(this);
for (auto&& child : stage->_children) {
@@ -406,9 +414,10 @@ protected:
* May return boost::none if it is not necessary to collect timing info.
*/
boost::optional<ScopedTimer> getOptTimer(OperationContext* opCtx) {
- if (_commonStats.executionTimeMillis && opCtx) {
- return {{opCtx->getServiceContext()->getFastClockSource(),
- _commonStats.executionTimeMillis.get_ptr()}};
+ if (opCtx) {
+ return scoped_timer_factory::make(opCtx->getServiceContext(),
+ _commonStats.executionTime.precision,
+ &_commonStats.executionTime.executionTimeEstimate);
}
return boost::none;
diff --git a/src/mongo/db/exec/scoped_timer.cpp b/src/mongo/db/exec/scoped_timer.cpp
index f33c498a57a..d7cc6064a7e 100644
--- a/src/mongo/db/exec/scoped_timer.cpp
+++ b/src/mongo/db/exec/scoped_timer.cpp
@@ -30,16 +30,11 @@
#include "mongo/platform/basic.h"
#include "mongo/db/exec/scoped_timer.h"
-#include "mongo/util/clock_source.h"
namespace mongo {
-
-ScopedTimer::ScopedTimer(ClockSource* cs, long long* counter)
- : _clock(cs), _counter(counter), _start(cs->now()) {}
+ScopedTimer::ScopedTimer(Microseconds* counter, TickSource* ts) : _counter(counter), _timer(ts) {}
ScopedTimer::~ScopedTimer() {
- long long elapsed = durationCount<Milliseconds>(_clock->now() - _start);
- *_counter += elapsed;
+ *_counter += _timer.elapsed();
}
-
} // namespace mongo
diff --git a/src/mongo/db/exec/scoped_timer.h b/src/mongo/db/exec/scoped_timer.h
index c11c424e59a..3feef551ced 100644
--- a/src/mongo/db/exec/scoped_timer.h
+++ b/src/mongo/db/exec/scoped_timer.h
@@ -29,16 +29,17 @@
#pragma once
-
+#include "mongo/stdx/variant.h"
+#include "mongo/util/clock_source.h"
+#include "mongo/util/clock_tick_source.h"
+#include "mongo/util/system_tick_source.h"
#include "mongo/util/time_support.h"
+#include "mongo/util/timer.h"
namespace mongo {
-
-class ClockSource;
-
/**
- * This class increments a counter by a rough estimate of the time elapsed since its
- * construction when it goes out of scope.
+ * The timer increments a counter by the time elapsed since its construction when it goes out of
+ * scope.
*/
class ScopedTimer {
ScopedTimer(const ScopedTimer&) = delete;
@@ -46,17 +47,14 @@ class ScopedTimer {
public:
ScopedTimer(ScopedTimer&& other) = default;
- ScopedTimer(ClockSource* cs, long long* counter);
+
+ ScopedTimer(Microseconds* counter, TickSource* clock);
~ScopedTimer();
private:
- ClockSource* const _clock;
// Reference to the counter that we are incrementing with the elapsed time.
- long long* _counter;
-
- // Time at which the timer was constructed.
- const Date_t _start;
+ Microseconds* const _counter;
+ Timer _timer;
};
-
} // namespace mongo
diff --git a/src/mongo/db/exec/scoped_timer_factory.cpp b/src/mongo/db/exec/scoped_timer_factory.cpp
new file mode 100644
index 00000000000..3b9a281e058
--- /dev/null
+++ b/src/mongo/db/exec/scoped_timer_factory.cpp
@@ -0,0 +1,50 @@
+/**
+ * Copyright (C) 2022-present MongoDB, Inc.
+ *
+ * This program is free software: you can redistribute it and/or modify
+ * it under the terms of the Server Side Public License, version 1,
+ * as published by MongoDB, Inc.
+ *
+ * This program is distributed in the hope that it will be useful,
+ * but WITHOUT ANY WARRANTY; without even the implied warranty of
+ * MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the
+ * Server Side Public License for more details.
+ *
+ * You should have received a copy of the Server Side Public License
+ * along with this program. If not, see
+ * <http://www.mongodb.com/licensing/server-side-public-license>.
+ *
+ * As a special exception, the copyright holders give permission to link the
+ * code of portions of this program with the OpenSSL library under certain
+ * conditions as described in each individual source file and distribute
+ * linked combinations including the program with the OpenSSL library. You
+ * must comply with the Server Side Public License in all respects for
+ * all of the code used other than as permitted herein. If you modify file(s)
+ * with this exception, you may extend this exception to your version of the
+ * file(s), but you are not obligated to do so. If you do not wish to do so,
+ * delete this exception statement from your version. If you delete this
+ * exception statement from all source files in the program, then also delete
+ * it in the license file.
+ */
+
+#include "mongo/db/exec/scoped_timer_factory.h"
+
+namespace mongo {
+namespace scoped_timer_factory {
+
+boost::optional<ScopedTimer> make(ServiceContext* context,
+ QueryExecTimerPrecision precision,
+ Microseconds* counter) {
+ invariant(context);
+ if (precision == QueryExecTimerPrecision::kMillis) {
+ return {{counter, context->getFastTickSource()}};
+ }
+ if (precision == QueryExecTimerPrecision::kMicros) {
+ return {{counter, context->getTickSource()}};
+ }
+
+ return boost::none;
+}
+
+} // namespace scoped_timer_factory
+} // namespace mongo
diff --git a/src/mongo/db/exec/scoped_timer_factory.h b/src/mongo/db/exec/scoped_timer_factory.h
new file mode 100644
index 00000000000..20e8bde1d79
--- /dev/null
+++ b/src/mongo/db/exec/scoped_timer_factory.h
@@ -0,0 +1,47 @@
+/**
+ * Copyright (C) 2022-present MongoDB, Inc.
+ *
+ * This program is free software: you can redistribute it and/or modify
+ * it under the terms of the Server Side Public License, version 1,
+ * as published by MongoDB, Inc.
+ *
+ * This program is distributed in the hope that it will be useful,
+ * but WITHOUT ANY WARRANTY; without even the implied warranty of
+ * MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the
+ * Server Side Public License for more details.
+ *
+ * You should have received a copy of the Server Side Public License
+ * along with this program. If not, see
+ * <http://www.mongodb.com/licensing/server-side-public-license>.
+ *
+ * As a special exception, the copyright holders give permission to link the
+ * code of portions of this program with the OpenSSL library under certain
+ * conditions as described in each individual source file and distribute
+ * linked combinations including the program with the OpenSSL library. You
+ * must comply with the Server Side Public License in all respects for
+ * all of the code used other than as permitted herein. If you modify file(s)
+ * with this exception, you may extend this exception to your version of the
+ * file(s), but you are not obligated to do so. If you do not wish to do so,
+ * delete this exception statement from your version. If you delete this
+ * exception statement from all source files in the program, then also delete
+ * it in the license file.
+ */
+
+#pragma once
+
+#include "mongo/db/exec/scoped_timer.h"
+#include "mongo/db/query/plan_summary_stats.h"
+#include "mongo/db/service_context.h"
+
+namespace mongo {
+namespace scoped_timer_factory {
+
+/**
+ * A factory helper to make a 'ScopedTimer'. The type of the underlying timer is based on the value
+ * of 'precision'.
+ */
+boost::optional<ScopedTimer> make(ServiceContext* context,
+ QueryExecTimerPrecision precision,
+ Microseconds* counter);
+} // namespace scoped_timer_factory
+} // namespace mongo
diff --git a/src/mongo/db/exec/subplan.cpp b/src/mongo/db/exec/subplan.cpp
index c2f2947cecc..eab7e0abe49 100644
--- a/src/mongo/db/exec/subplan.cpp
+++ b/src/mongo/db/exec/subplan.cpp
@@ -157,8 +157,8 @@ Status SubplanStage::choosePlanWholeQuery(PlanYieldPolicy* yieldPolicy) {
}
Status SubplanStage::pickBestPlan(PlanYieldPolicy* yieldPolicy) {
- // Adds the amount of time taken by pickBestPlan() to executionTimeMillis. There's lots of
- // work that happens here, so this is needed for the time accounting to make sense.
+ // Adds the amount of time taken by pickBestPlan() to executionTime. There's lots of work that
+ // happens here, so this is needed for the time accounting to make sense.
auto optTimer = getOptTimer();
// During plan selection, the list of indices we are using to plan must remain stable, so the
diff --git a/src/mongo/db/pipeline/document_source.cpp b/src/mongo/db/pipeline/document_source.cpp
index c9358ebdc73..32ef38a78b3 100644
--- a/src/mongo/db/pipeline/document_source.cpp
+++ b/src/mongo/db/pipeline/document_source.cpp
@@ -64,7 +64,7 @@ DocumentSource::DocumentSource(const StringData stageName,
const intrusive_ptr<ExpressionContext>& pCtx)
: pSource(nullptr), pExpCtx(pCtx), _commonStats(stageName.rawData()) {
if (pExpCtx->shouldCollectDocumentSourceExecStats()) {
- _commonStats.executionTimeMillis.emplace(0);
+ _commonStats.executionTime.emplace(0);
}
}
diff --git a/src/mongo/db/pipeline/document_source.h b/src/mongo/db/pipeline/document_source.h
index a3ebb050dad..ada9da058d6 100644
--- a/src/mongo/db/pipeline/document_source.h
+++ b/src/mongo/db/pipeline/document_source.h
@@ -47,6 +47,7 @@
#include "mongo/db/exec/document_value/value.h"
#include "mongo/db/exec/plan_stats.h"
#include "mongo/db/exec/scoped_timer.h"
+#include "mongo/db/exec/scoped_timer_factory.h"
#include "mongo/db/generic_cursor.h"
#include "mongo/db/jsobj.h"
#include "mongo/db/matcher/expression_algo.h"
@@ -358,11 +359,10 @@ public:
auto serviceCtx = pExpCtx->opCtx->getServiceContext();
invariant(serviceCtx);
- auto fcs = serviceCtx->getFastClockSource();
- invariant(fcs);
- invariant(_commonStats.executionTimeMillis);
- ScopedTimer timer(fcs, _commonStats.executionTimeMillis.get_ptr());
+ auto timer = scoped_timer_factory::make(
+ serviceCtx, QueryExecTimerPrecision::kMillis, _commonStats.executionTime.get_ptr());
+
++_commonStats.works;
GetNextResult next = doGetNext();
diff --git a/src/mongo/db/pipeline/pipeline.cpp b/src/mongo/db/pipeline/pipeline.cpp
index af52bd79435..73da96013dc 100644
--- a/src/mongo/db/pipeline/pipeline.cpp
+++ b/src/mongo/db/pipeline/pipeline.cpp
@@ -64,9 +64,10 @@ Value appendCommonExecStats(Value docSource, const CommonStats& stats) {
invariant(docSource.getType() == BSONType::Object);
MutableDocument doc(docSource.getDocument());
auto nReturned = static_cast<long long>(stats.advanced);
- invariant(stats.executionTimeMillis);
- auto executionTimeMillisEstimate = static_cast<long long>(*stats.executionTimeMillis);
doc.addField("nReturned", Value(nReturned));
+
+ invariant(stats.executionTime);
+ auto executionTimeMillisEstimate = durationCount<Milliseconds>(*stats.executionTime);
doc.addField("executionTimeMillisEstimate", Value(executionTimeMillisEstimate));
return Value(doc.freeze());
}
diff --git a/src/mongo/db/query/classic_plan_cache.cpp b/src/mongo/db/query/classic_plan_cache.cpp
index 79975991e4e..f4bbff1af2b 100644
--- a/src/mongo/db/query/classic_plan_cache.cpp
+++ b/src/mongo/db/query/classic_plan_cache.cpp
@@ -152,8 +152,8 @@ bool shouldCacheQuery(const CanonicalQuery& query) {
//
// There is one exception: $lookup's implementation in the DocumentSource engine relies on
// caching the plan on the inner side in order to avoid repeating the planning process for every
- // document on the outer side. To ensure that the 'executionTimeMillis' value is accurate for
- // $lookup, we allow the inner side to use the cache even if the query is an explain.
+ // document on the outer side. To ensure that the 'executionTime' value is accurate for $lookup,
+ // we allow the inner side to use the cache even if the query is an explain.
tassert(6497600, "expCtx is null", query.getExpCtxRaw());
if (query.getExplain() && !query.getExpCtxRaw()->inLookup) {
return false;
diff --git a/src/mongo/db/query/explain.cpp b/src/mongo/db/query/explain.cpp
index 3bf922ceb8d..faf610fc5ff 100644
--- a/src/mongo/db/query/explain.cpp
+++ b/src/mongo/db/query/explain.cpp
@@ -188,7 +188,18 @@ void generateSinglePlanExecutionInfo(const PlanExplainer::PlanStatsDetails& deta
if (totalTimeMillis) {
out->appendNumber("executionTimeMillis", *totalTimeMillis);
} else {
- out->appendNumber("executionTimeMillisEstimate", summary->executionTimeMillisEstimate);
+ if (summary->executionTime.precision == QueryExecTimerPrecision::kMicros) {
+ out->appendNumber(
+ "executionTimeMillisEstimate",
+ durationCount<Milliseconds>(summary->executionTime.executionTimeEstimate));
+ out->appendNumber(
+ "executionTimeMicros",
+ durationCount<Microseconds>(summary->executionTime.executionTimeEstimate));
+ } else if (summary->executionTime.precision == QueryExecTimerPrecision::kMillis) {
+ out->appendNumber(
+ "executionTimeMillisEstimate",
+ durationCount<Milliseconds>(summary->executionTime.executionTimeEstimate));
+ }
}
out->appendNumber("totalKeysExamined", static_cast<long long>(summary->totalKeysExamined));
diff --git a/src/mongo/db/query/plan_explainer_impl.cpp b/src/mongo/db/query/plan_explainer_impl.cpp
index b645681849f..c5ee9377af2 100644
--- a/src/mongo/db/query/plan_explainer_impl.cpp
+++ b/src/mongo/db/query/plan_explainer_impl.cpp
@@ -218,8 +218,9 @@ void statsToBSON(const PlanStageStats& stats,
if (verbosity >= ExplainOptions::Verbosity::kExecStats) {
bob->appendNumber("nReturned", static_cast<long long>(stats.common.advanced));
// Include executionTimeMillis if it was recorded.
- if (stats.common.executionTimeMillis) {
- bob->appendNumber("executionTimeMillisEstimate", *stats.common.executionTimeMillis);
+ if (stats.common.executionTime) {
+ bob->appendNumber("executionTimeMillisEstimate",
+ durationCount<Milliseconds>(*stats.common.executionTime));
}
bob->appendNumber("works", static_cast<long long>(stats.common.works));
@@ -532,8 +533,9 @@ PlanSummaryStats collectExecutionStatsSummary(const PlanStageStats* stats,
PlanSummaryStats summary;
summary.nReturned = stats->common.advanced;
- if (stats->common.executionTimeMillis) {
- summary.executionTimeMillisEstimate = *stats->common.executionTimeMillis;
+ if (stats->common.executionTime) {
+ summary.executionTime.executionTimeEstimate = *stats->common.executionTime;
+ summary.executionTime.precision = QueryExecTimerPrecision::kMillis;
}
// Flatten the stats tree into a list.
diff --git a/src/mongo/db/query/plan_explainer_sbe.cpp b/src/mongo/db/query/plan_explainer_sbe.cpp
index fea5b81cea4..e14eebb59b4 100644
--- a/src/mongo/db/query/plan_explainer_sbe.cpp
+++ b/src/mongo/db/query/plan_explainer_sbe.cpp
@@ -238,9 +238,18 @@ void statsToBSONHelper(const sbe::PlanStageStats* stats,
// Some top-level exec stats get pulled out of the root stage.
bob->appendNumber("nReturned", static_cast<long long>(stats->common.advances));
- // Include executionTimeMillis if it was recorded.
- if (stats->common.executionTimeMillis) {
- bob->appendNumber("executionTimeMillisEstimate", *stats->common.executionTimeMillis);
+ // Include the execution time if it was recorded.
+ if (stats->common.executionTime.precision == QueryExecTimerPrecision::kMillis) {
+ bob->appendNumber(
+ "executionTimeMillisEstimate",
+ durationCount<Milliseconds>(stats->common.executionTime.executionTimeEstimate));
+ } else if (stats->common.executionTime.precision == QueryExecTimerPrecision::kMicros) {
+ bob->appendNumber(
+ "executionTimeMillisEstimate",
+ durationCount<Milliseconds>(stats->common.executionTime.executionTimeEstimate));
+ bob->appendNumber(
+ "executionTimeMicros",
+ durationCount<Microseconds>(stats->common.executionTime.executionTimeEstimate));
}
bob->appendNumber("opens", static_cast<long long>(stats->common.opens));
bob->appendNumber("closes", static_cast<long long>(stats->common.closes));
diff --git a/src/mongo/db/query/plan_summary_stats.h b/src/mongo/db/query/plan_summary_stats.h
index ac80b6505f3..a3470609467 100644
--- a/src/mongo/db/query/plan_summary_stats.h
+++ b/src/mongo/db/query/plan_summary_stats.h
@@ -30,12 +30,24 @@
#pragma once
#include <optional>
+#include <set>
#include <string>
#include "mongo/util/container_size_helper.h"
namespace mongo {
+// The precision of 'executionTime'. Note that 'kMicros' precision requires a precise timer which
+// is also slower than the default timer.
+enum class QueryExecTimerPrecision { kNoTiming = 0, kMicros, kMillis };
+
+struct QueryExecTime {
+ // Precision/unit of 'executionTimeEstimate'.
+ QueryExecTimerPrecision precision = QueryExecTimerPrecision::kNoTiming;
+ // Time elapsed while executing this plan.
+ Microseconds executionTimeEstimate{0};
+};
+
/**
* A container for the summary statistics that the profiler, slow query log, and
* other non-explain debug mechanisms may want to collect.
@@ -71,7 +83,7 @@ struct PlanSummaryStats {
long long collectionScansNonTailable = 0;
// Time elapsed while executing this plan.
- long long executionTimeMillisEstimate = 0;
+ QueryExecTime executionTime;
// Did this plan use an in-memory sort stage?
bool hasSortStage = false;
diff --git a/src/mongo/db/query/query_knobs.idl b/src/mongo/db/query/query_knobs.idl
index 8e47323c1ef..831334ed790 100644
--- a/src/mongo/db/query/query_knobs.idl
+++ b/src/mongo/db/query/query_knobs.idl
@@ -874,6 +874,14 @@ server_parameters:
validator:
gt: 0
lt: 16777216
+
+ internalMeasureQueryExecutionTimeInMicroseconds:
+ description: "If true, the explain results include an additional 'executionTimeMicros' field to
+ represent the execution time of each plan stage in microseconds"
+ set_at: [ startup ]
+ cpp_varname: "internalMeasureQueryExecutionTimeInMicroseconds"
+ cpp_vartype: AtomicWord<bool>
+ default: false
internalQueryFLEAlwaysUseHighCardinalityMode:
description: "Boolean flag to force FLE to always use low selectivity mode"
diff --git a/src/mongo/db/service_context.cpp b/src/mongo/db/service_context.cpp
index 013e3209f95..4bbefa82ba4 100644
--- a/src/mongo/db/service_context.cpp
+++ b/src/mongo/db/service_context.cpp
@@ -102,6 +102,7 @@ ServiceContext::ServiceContext()
: _opIdRegistry(UniqueOperationIdRegistry::create()),
_tickSource(std::make_unique<SystemTickSource>()),
_fastClockSource(std::make_unique<SystemClockSource>()),
+ _clockTickSource(_fastClockSource.get()),
_preciseClockSource(std::make_unique<SystemClockSource>()) {}
@@ -212,6 +213,7 @@ void ServiceContext::setTickSource(std::unique_ptr<TickSource> newSource) {
}
void ServiceContext::setFastClockSource(std::unique_ptr<ClockSource> newSource) {
+ _clockTickSource.setClockSource(newSource.get());
_fastClockSource = std::move(newSource);
}
diff --git a/src/mongo/db/service_context.h b/src/mongo/db/service_context.h
index 10dd5e33203..7a8ec435a3a 100644
--- a/src/mongo/db/service_context.h
+++ b/src/mongo/db/service_context.h
@@ -45,6 +45,7 @@
#include "mongo/stdx/unordered_set.h"
#include "mongo/transport/session.h"
#include "mongo/util/clock_source.h"
+#include "mongo/util/clock_tick_source.h"
#include "mongo/util/concurrency/with_lock.h"
#include "mongo/util/decorable.h"
#include "mongo/util/hierarchical_acquisition.h"
@@ -545,6 +546,13 @@ public:
}
/**
+ * Returns the tick/clock source that wraps '_fastClockSource' in this context.
+ */
+ TickSource* getFastTickSource() {
+ return &_clockTickSource;
+ }
+
+ /**
* Get a ClockSource implementation that may be less precise than the _preciseClockSource but
* may be cheaper to call.
*/
@@ -566,6 +574,12 @@ public:
void setTickSource(std::unique_ptr<TickSource> newSource);
/**
+ * Replaces the current tick/clock source with a new one. In other words, the old source will be
+ * destroyed. So make sure that no one is using the old source when calling this.
+ */
+ void setFastTickSource(std::unique_ptr<TickSource> newSource);
+
+ /**
* Call this method with a ClockSource implementation that may be less precise than
* the _preciseClockSource but may be cheaper to call.
*/
@@ -754,6 +768,12 @@ private:
SyncUnique<ClockSource> _fastClockSource;
/**
+ * A type of TickSource that wraps '_fastClockSource'. Note that '_clockTickSource' does not own
+ * '_fastClockSource'.
+ */
+ ClockTickSource _clockTickSource;
+
+ /**
* A ClockSource implementation that is very precise but may be expensive to call.
*/
SyncUnique<ClockSource> _preciseClockSource;
diff --git a/src/mongo/util/clock_tick_source.cpp b/src/mongo/util/clock_tick_source.cpp
new file mode 100644
index 00000000000..614b10c6ea2
--- /dev/null
+++ b/src/mongo/util/clock_tick_source.cpp
@@ -0,0 +1,49 @@
+/**
+ * Copyright (C) 2022-present MongoDB, Inc.
+ *
+ * This program is free software: you can redistribute it and/or modify
+ * it under the terms of the Server Side Public License, version 1,
+ * as published by MongoDB, Inc.
+ *
+ * This program is distributed in the hope that it will be useful,
+ * but WITHOUT ANY WARRANTY; without even the implied warranty of
+ * MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the
+ * Server Side Public License for more details.
+ *
+ * You should have received a copy of the Server Side Public License
+ * along with this program. If not, see
+ * <http://www.mongodb.com/licensing/server-side-public-license>.
+ *
+ * As a special exception, the copyright holders give permission to link the
+ * code of portions of this program with the OpenSSL library under certain
+ * conditions as described in each individual source file and distribute
+ * linked combinations including the program with the OpenSSL library. You
+ * must comply with the Server Side Public License in all respects for
+ * all of the code used other than as permitted herein. If you modify file(s)
+ * with this exception, you may extend this exception to your version of the
+ * file(s), but you are not obligated to do so. If you do not wish to do so,
+ * delete this exception statement from your version. If you delete this
+ * exception statement from all source files in the program, then also delete
+ * it in the license file.
+ */
+
+#include "mongo/util/clock_tick_source.h"
+
+namespace mongo {
+
+namespace {
+
+const int64_t kMillisPerSecond = 1000;
+const TickSource::Tick ticksPerSecond = kMillisPerSecond;
+
+} // namespace
+
+TickSource::Tick ClockTickSource::getTicks() {
+ return _cs->now().toMillisSinceEpoch();
+}
+
+TickSource::Tick ClockTickSource::getTicksPerSecond() {
+ return ticksPerSecond;
+}
+
+} // namespace mongo
diff --git a/src/mongo/util/clock_tick_source.h b/src/mongo/util/clock_tick_source.h
new file mode 100644
index 00000000000..3e9105019a9
--- /dev/null
+++ b/src/mongo/util/clock_tick_source.h
@@ -0,0 +1,60 @@
+/**
+ * Copyright (C) 2022-present MongoDB, Inc.
+ *
+ * This program is free software: you can redistribute it and/or modify
+ * it under the terms of the Server Side Public License, version 1,
+ * as published by MongoDB, Inc.
+ *
+ * This program is distributed in the hope that it will be useful,
+ * but WITHOUT ANY WARRANTY; without even the implied warranty of
+ * MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the
+ * Server Side Public License for more details.
+ *
+ * You should have received a copy of the Server Side Public License
+ * along with this program. If not, see
+ * <http://www.mongodb.com/licensing/server-side-public-license>.
+ *
+ * As a special exception, the copyright holders give permission to link the
+ * code of portions of this program with the OpenSSL library under certain
+ * conditions as described in each individual source file and distribute
+ * linked combinations including the program with the OpenSSL library. You
+ * must comply with the Server Side Public License in all respects for
+ * all of the code used other than as permitted herein. If you modify file(s)
+ * with this exception, you may extend this exception to your version of the
+ * file(s), but you are not obligated to do so. If you do not wish to do so,
+ * delete this exception statement from your version. If you delete this
+ * exception statement from all source files in the program, then also delete
+ * it in the license file.
+ */
+
+#pragma once
+
+#include "mongo/util/clock_source.h"
+#include "mongo/util/tick_source.h"
+
+namespace mongo {
+
+/**
+ * Tick source based on a 'ClockSource'. Note that this precision of this 'TickSource' depends on
+ * the precision of the 'ClockSource' which currently only supports milliseconds.
+ */
+class ClockTickSource final : public TickSource {
+public:
+ explicit ClockTickSource(ClockSource* cs) : _cs(cs) {}
+
+ TickSource::Tick getTicks() override;
+
+ TickSource::Tick getTicksPerSecond() override;
+
+ ClockSource* getClockSource() {
+ return _cs;
+ }
+
+ void setClockSource(ClockSource* cs) {
+ _cs = cs;
+ }
+
+private:
+ ClockSource* _cs = nullptr;
+};
+} // namespace mongo
diff --git a/src/mongo/util/tick_source_test.cpp b/src/mongo/util/tick_source_test.cpp
index cf08b69cbdc..3d14c4ac1fc 100644
--- a/src/mongo/util/tick_source_test.cpp
+++ b/src/mongo/util/tick_source_test.cpp
@@ -30,8 +30,11 @@
#include "mongo/platform/basic.h"
#include "mongo/unittest/unittest.h"
+#include "mongo/util/clock_source_mock.h"
+#include "mongo/util/clock_tick_source.h"
#include "mongo/util/tick_source.h"
#include "mongo/util/tick_source_mock.h"
+#include "mongo/util/time_support.h"
namespace mongo {
namespace {
@@ -66,5 +69,25 @@ TEST(TickSourceTest, SpansToDurationConversion) {
ASSERT_EQ(tsSecs.spanTo<Microseconds>(zero, ten).count(), 10 * 1000 * 1000);
ASSERT_EQ(tsSecs.spanTo<Microseconds>(ten, zero).count(), 0);
}
+
+TEST(TickSourceTest, ClockTickSourceTest) {
+ ClockSourceMock mockSource;
+ std::unique_ptr<TickSource> ts = std::make_unique<ClockTickSource>(&mockSource);
+ auto start = ts->getTicks();
+ mockSource.advance(Milliseconds(10));
+ auto end = ts->getTicks();
+ auto elapsedSecs = ts->spanTo<Seconds>(start, end).count();
+ auto elapsedMils = ts->spanTo<Milliseconds>(start, end).count();
+ auto elapsedMics = ts->spanTo<Microseconds>(start, end).count();
+
+ ASSERT_LT(elapsedSecs, 1);
+ ASSERT_GTE(elapsedSecs, 0);
+
+ ASSERT_LTE(elapsedMils, 11);
+ ASSERT_GTE(elapsedMils, 10);
+
+ ASSERT_LTE(elapsedMics, 11 * 1000);
+ ASSERT_GTE(elapsedMics, 10 * 1000);
+}
} // namespace
} // namespace mongo