diff options
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 |