SERVER-67101 Support microsecond precision in ScopedTimer

14 files changed, 147 insertions, 59 deletions

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