SERVER-63642 Add serverStatus histogram metrics to measure multi-planning performance

5 files changed, 204 insertions, 10 deletions

diff --git a/src/mongo/db/commands/server_status_metric.h b/src/mongo/db/commands/server_status_metric.h
index f64327908e7..ff546527a8d 100644
--- a/src/mongo/db/commands/server_status_metric.h
+++ b/src/mongo/db/commands/server_status_metric.h
@@ -77,10 +77,6 @@ public:
     ServerStatusMetricField(const std::string& name, const T* t)
         : ServerStatusMetric(name), _t(t) {}
 
-    const T* get() {
-        return _t;
-    }
-
     virtual void appendAtLeaf(BSONObjBuilder& b) const {
         b.append(_leafName, *_t);
     }
diff --git a/src/mongo/db/exec/multi_plan.cpp b/src/mongo/db/exec/multi_plan.cpp
index f7ca2b1432b..def29719b63 100644
--- a/src/mongo/db/exec/multi_plan.cpp
+++ b/src/mongo/db/exec/multi_plan.cpp
@@ -50,14 +50,12 @@
 #include "mongo/db/query/plan_ranker.h"
 #include "mongo/db/query/plan_ranker_util.h"
 #include "mongo/logv2/log.h"
+#include "mongo/util/histogram.h"
 #include "mongo/util/str.h"
 
 namespace mongo {
 
-using std::endl;
-using std::list;
 using std::unique_ptr;
-using std::vector;
 
 // static
 const char* MultiPlanStage::kStageType = "MULTI_PLAN";
@@ -69,6 +67,65 @@ void markShouldCollectTimingInfoOnSubtree(PlanStage* root) {
         markShouldCollectTimingInfoOnSubtree(child.get());
     }
 }
+
+Counter64 classicMicrosTotal;
+Counter64 classicWorksTotal;
+Counter64 classicCount;
+
+Histogram<uint64_t> classicMicrosHistogram{{0,
+                                            1024,
+                                            4096,
+                                            16384,
+                                            65536,
+                                            262144,
+                                            1048576,
+                                            4194304,
+                                            16777216,
+                                            67108864,
+                                            268435456,
+                                            1073741824}};
+Histogram<uint64_t> classicWorksHistogram{{0, 128, 256, 512, 1024, 2048, 4096, 8192, 16384, 32768}};
+Histogram<uint64_t> classicNumPlansHistogram{{0, 2, 4, 8, 16, 32}};
+
+/**
+ * Aggregation of the total number of microseconds spent (in the classic multiplanner).
+ */
+ServerStatusMetricField<Counter64> classicMicrosTotalDisplay("query.multiPlanner.classicMicros",
+                                                             &classicMicrosTotal);
+
+/**
+ * Aggregation of the total number of "works" performed (in the classic multiplanner).
+ */
+ServerStatusMetricField<Counter64> classicWorksTotalDisplay("query.multiPlanner.classicWorks",
+                                                            &classicWorksTotal);
+
+/**
+ * Aggregation of the total number of invocations (of the classic multiplanner).
+ */
+ServerStatusMetricField<Counter64> classicCountDisplay("query.multiPlanner.classicCount",
+                                                       &classicCount);
+
+/**
+ * An element in this histogram is the number of microseconds spent in an invocation (of the
+ * classic multiplanner).
+ */
+ServerStatusMetricField<Histogram<uint64_t>> classicMicrosHistogramDisplay(
+    "query.multiPlanner.histograms.classicMicros", classicMicrosHistogram);
+
+/**
+ * An element in this histogram is the number of "works" performed during an invocation (of the
+ * classic multiplanner).
+ */
+ServerStatusMetricField<Histogram<uint64_t>> classicWorksHistogramDisplay(
+    "query.multiPlanner.histograms.classicWorks", classicWorksHistogram);
+
+/**
+ * An element in this histogram is the number of plans in the candidate set of an invocation (of the
+ * classic multiplanner).
+ */
+ServerStatusMetricField<Histogram<uint64_t>> classicNumPlansHistogramDisplay(
+    "query.multiPlanner.histograms.classicNumPlans", classicNumPlansHistogram);
+
 }  // namespace
 
 MultiPlanStage::MultiPlanStage(ExpressionContext* expCtx,
@@ -163,6 +220,12 @@ Status MultiPlanStage::pickBestPlan(PlanYieldPolicy* yieldPolicy) {
     // make sense.
     auto optTimer = getOptTimer();
 
+    auto tickSource = opCtx()->getServiceContext()->getTickSource();
+    auto startTicks = tickSource->getTicks();
+
+    classicNumPlansHistogram.increment(_candidates.size());
+    classicCount.increment();
+
     const size_t numWorks =
         trial_period::getTrialPeriodMaxWorks(opCtx(),
                                              collection(),
@@ -172,16 +235,25 @@ Status MultiPlanStage::pickBestPlan(PlanYieldPolicy* yieldPolicy) {
 
     try {
         // Work the plans, stopping when a plan hits EOF or returns some fixed number of results.
-        for (size_t ix = 0; ix < numWorks; ++ix) {
+        size_t ix = 0;
+        for (; ix < numWorks; ++ix) {
             bool moreToDo = workAllPlans(numResults, yieldPolicy);
             if (!moreToDo) {
                 break;
             }
         }
+        auto totalWorks = ix * _candidates.size();
+        classicWorksHistogram.increment(totalWorks);
+        classicWorksTotal.increment(totalWorks);
     } catch (DBException& e) {
         return e.toStatus().withContext("error while multiplanner was selecting best plan");
     }
 
+    auto durationMicros = durationCount<Microseconds>(
+        tickSource->ticksTo<Microseconds>(tickSource->getTicks() - startTicks));
+    classicMicrosHistogram.increment(durationMicros);
+    classicMicrosTotal.increment(durationMicros);
+
     // After picking best plan, ranking will own plan stats from candidate solutions (winner and
     // losers).
     auto statusWithRanking = plan_ranker::pickBestPlan<PlanStageStats>(_candidates);
diff --git a/src/mongo/db/ftdc/ftdc_server.cpp b/src/mongo/db/ftdc/ftdc_server.cpp
index 2d51d5c202b..19cc3568b08 100644
--- a/src/mongo/db/ftdc/ftdc_server.cpp
+++ b/src/mongo/db/ftdc/ftdc_server.cpp
@@ -231,6 +231,10 @@ public:
         // frequent schema changes.
         commandBuilder.append("transactions", BSON("includeLastCommitted" << false));
 
+        // Exclude detailed query planning statistics.
+        commandBuilder.append("metrics",
+                              BSON("query" << BSON("multiPlanner" << BSON("histograms" << false))));
+
         if (gDiagnosticDataCollectionEnableLatencyHistograms.load()) {
             BSONObjBuilder subObjBuilder(commandBuilder.subobjStart("opLatencies"));
             subObjBuilder.append("histograms", true);
diff --git a/src/mongo/db/query/sbe_runtime_planner.cpp b/src/mongo/db/query/sbe_runtime_planner.cpp
index 014955a2bca..74e09a76ecd 100644
--- a/src/mongo/db/query/sbe_runtime_planner.cpp
+++ b/src/mongo/db/query/sbe_runtime_planner.cpp
@@ -35,9 +35,68 @@
 #include "mongo/db/exec/trial_period_utils.h"
 #include "mongo/db/exec/trial_run_tracker.h"
 #include "mongo/db/query/plan_executor_sbe.h"
+#include "mongo/util/histogram.h"
 
 namespace mongo::sbe {
 namespace {
+
+Counter64 sbeMicrosTotal;
+Counter64 sbeNumReadsTotal;
+Counter64 sbeCount;
+
+Histogram<uint64_t> sbeMicrosHistogram{{0,
+                                        1024,
+                                        4096,
+                                        16384,
+                                        65536,
+                                        262144,
+                                        1048576,
+                                        4194304,
+                                        16777216,
+                                        67108864,
+                                        268435456,
+                                        1073741824}};
+Histogram<uint64_t> sbeNumReadsHistogram{{0, 128, 256, 512, 1024, 2048, 4096, 8192, 16384, 32768}};
+Histogram<uint64_t> sbeNumPlansHistogram{{0, 2, 4, 8, 16, 32}};
+
+/**
+ * Aggregation of the total number of microseconds spent (in SBE multiplanner).
+ */
+ServerStatusMetricField<Counter64> sbeMicrosTotalDisplay("query.multiPlanner.sbeMicros",
+                                                         &sbeMicrosTotal);
+
+/**
+ * Aggregation of the total number of reads done (in SBE multiplanner).
+ */
+ServerStatusMetricField<Counter64> sbeNumReadsTotalDisplay("query.multiPlanner.sbeNumReads",
+                                                           &sbeNumReadsTotal);
+
+/**
+ * Aggregation of the total number of invocations (of the SBE multiplanner).
+ */
+ServerStatusMetricField<Counter64> sbeCountDisplay("query.multiPlanner.sbeCount", &sbeCount);
+
+/**
+ * An element in this histogram is the number of microseconds spent in an invocation (of the SBE
+ * multiplanner).
+ */
+ServerStatusMetricField<Histogram<uint64_t>> sbeMicrosHistogramDisplay(
+    "query.multiPlanner.histograms.sbeMicros", sbeMicrosHistogram);
+
+/**
+ * An element in this histogram is the number of reads performance during an invocation (of the SBE
+ * multiplanner).
+ */
+ServerStatusMetricField<Histogram<uint64_t>> sbeNumReadsHistogramDisplay(
+    "query.multiPlanner.histograms.sbeNumReads", sbeNumReadsHistogram);
+
+/**
+ * An element in this histogram is the number of plans in the candidate set of an invocation (of the
+ * SBE multiplanner).
+ */
+ServerStatusMetricField<Histogram<uint64_t>> sbeNumPlansHistogramDisplay(
+    "query.multiPlanner.histograms.sbeNumPlans", sbeNumPlansHistogram);
+
 /**
  * Fetches a next document form the given plan stage tree and returns 'true' if the plan stage
  * returns EOF, or throws 'TrialRunTracker::EarlyExitException' exception. Otherwise, the
@@ -156,6 +215,11 @@ std::vector<plan_ranker::CandidatePlan> BaseRuntimePlanner::collectExecutionStat
 
     const auto maxNumResults{trial_period::getTrialPeriodNumToReturn(_cq)};
 
+    auto tickSource = _opCtx->getServiceContext()->getTickSource();
+    auto startTicks = tickSource->getTicks();
+    sbeNumPlansHistogram.increment(solutions.size());
+    sbeCount.increment();
+
     // Determine which plans are blocking and which are non blocking. The non blocking plans will
     // be run first in order to provide an upper bound on the number of reads allowed for the
     // blocking plans.
@@ -184,6 +248,8 @@ std::vector<plan_ranker::CandidatePlan> BaseRuntimePlanner::collectExecutionStat
     // plans which could artificially favor the blocking plans.
     const size_t trackerResultsBudget = nonBlockingPlanIndexes.empty() ? maxNumResults : 0;
 
+    uint64_t totalNumReads = 0;
+
     auto runPlans = [&](const std::vector<size_t>& planIndexes, size_t& maxNumReads) -> void {
         for (auto planIndex : planIndexes) {
             // Prepare the plan.
@@ -210,17 +276,29 @@ std::vector<plan_ranker::CandidatePlan> BaseRuntimePlanner::collectExecutionStat
             currentCandidate.clonedPlan.emplace(std::move(origPlan));
             executeCandidateTrial(&currentCandidate, maxNumResults);
 
+            auto reads = tracker->getMetric<TrialRunTracker::TrialRunMetric::kNumReads>();
+            // We intentionally increment the metrics outside of the isOk/existedEarly check.
+            totalNumReads += reads;
+
             // Reduce the number of reads the next candidates are allocated if this candidate is
             // more efficient than the current bound.
             if (currentCandidate.status.isOK() && !currentCandidate.exitedEarly) {
-                maxNumReads = std::min(
-                    maxNumReads, tracker->getMetric<TrialRunTracker::TrialRunMetric::kNumReads>());
+                maxNumReads = std::min(maxNumReads, reads);
             }
         }
     };
 
     runPlans(nonBlockingPlanIndexes, maxTrialPeriodNumReads);
     runPlans(blockingPlanIndexes, maxTrialPeriodNumReads);
+
+    sbeNumReadsHistogram.increment(totalNumReads);
+    sbeNumReadsTotal.increment(totalNumReads);
+
+    auto durationMicros = durationCount<Microseconds>(
+        tickSource->ticksTo<Microseconds>(tickSource->getTicks() - startTicks));
+    sbeMicrosHistogram.increment(durationMicros);
+    sbeMicrosTotal.increment(durationMicros);
+
     return candidates;
 }
 }  // namespace mongo::sbe
diff --git a/src/mongo/util/histogram.h b/src/mongo/util/histogram.h
index 0a07c82d9bc..78ba29664ba 100644
--- a/src/mongo/util/histogram.h
+++ b/src/mongo/util/histogram.h
@@ -184,4 +184,48 @@ void appendHistogram(BSONObjBuilder& bob, const Histogram<T>& hist, const String
     histBob.append("totalCount", totalCount);
 }
 
+namespace histogram_detail {
+/**
+ * Append the histogram as an array of {bound: <lower>, count: <count>} objects.
+ */
+template <typename T>
+void appendHistogramAsArray(const Histogram<T>& hist,
+                            const StringData histKey,
+                            bool includeFirstBucket,
+                            BSONObjBuilder& bob) {
+    BSONArrayBuilder histBob(bob.subarrayStart(histKey));
+
+    for (auto&& [count, lower, upper] : hist) {
+        // First bucket is indicated by 'lower' = nullptr.
+        if (lower) {
+            histBob.append(
+                BSON("lowerBound" << static_cast<long long>(*lower) << "count" << count));
+        } else if (includeFirstBucket) {
+            histBob.append(BSON("lowerBound"
+                                << "-INF"
+                                << "count" << count));
+        }
+    }
+}
+}  // namespace histogram_detail
+
+/**
+ * A metric reported in serverStatus with type histogram. This is a partial specialization of
+ * ServerStatusMetricField<T>. We cannot include it there due to cyclic header dependency via
+ * "commands.h".
+ */
+template <typename T>
+class ServerStatusMetricField<Histogram<T>> : public ServerStatusMetric {
+public:
+    ServerStatusMetricField(const std::string& name, const Histogram<T>& t)
+        : ServerStatusMetric(name), _hist(t) {}
+
+    virtual void appendAtLeaf(BSONObjBuilder& b) const {
+        histogram_detail::appendHistogramAsArray(_hist, _leafName, false, b);
+    }
+
+private:
+    const Histogram<T>& _hist;
+};
+
 }  // namespace mongo