SERVER-18468 add 'fromMultiPlanner' and 'replanned' flags to slow command logs

17 files changed, 62 insertions, 17 deletions

diff --git a/src/mongo/db/commands/count_cmd.cpp b/src/mongo/db/commands/count_cmd.cpp
index 68630694f77..f22b573d65d 100644
--- a/src/mongo/db/commands/count_cmd.cpp
+++ b/src/mongo/db/commands/count_cmd.cpp
@@ -165,6 +165,8 @@ public:
         if (collection) {
             collection->infoCache()->notifyOfQuery(txn, summaryStats.indexesUsed);
         }
+        CurOp::get(txn)->debug().fromMultiPlanner = summaryStats.fromMultiPlanner;
+        CurOp::get(txn)->debug().replanned = summaryStats.replanned;
 
         // Plan is done executing. We just need to pull the count out of the root stage.
         invariant(STAGE_COUNT == exec->getRootStage()->stageType());
diff --git a/src/mongo/db/commands/distinct.cpp b/src/mongo/db/commands/distinct.cpp
index cf8d0007db0..09f41a80f1a 100644
--- a/src/mongo/db/commands/distinct.cpp
+++ b/src/mongo/db/commands/distinct.cpp
@@ -232,6 +232,8 @@ public:
         PlanSummaryStats stats;
         Explain::getSummaryStats(*executor.getValue(), &stats);
         collection->infoCache()->notifyOfQuery(txn, stats.indexesUsed);
+        CurOp::get(txn)->debug().fromMultiPlanner = stats.fromMultiPlanner;
+        CurOp::get(txn)->debug().replanned = stats.replanned;
 
         verify(start == bb.buf());
 
diff --git a/src/mongo/db/commands/find_and_modify.cpp b/src/mongo/db/commands/find_and_modify.cpp
index c47eb9c839d..96c7d6f20c0 100644
--- a/src/mongo/db/commands/find_and_modify.cpp
+++ b/src/mongo/db/commands/find_and_modify.cpp
@@ -411,6 +411,8 @@ public:
                 if (collection) {
                     collection->infoCache()->notifyOfQuery(txn, summaryStats.indexesUsed);
                 }
+                CurOp::get(txn)->debug().fromMultiPlanner = summaryStats.fromMultiPlanner;
+                CurOp::get(txn)->debug().replanned = summaryStats.replanned;
 
                 // Fill out OpDebug with the number of deleted docs.
                 CurOp::get(txn)->debug().ndeleted = getDeleteStats(exec.get())->docsDeleted;
diff --git a/src/mongo/db/commands/geo_near_cmd.cpp b/src/mongo/db/commands/geo_near_cmd.cpp
index 3b5d0ccee6c..c256bd140e9 100644
--- a/src/mongo/db/commands/geo_near_cmd.cpp
+++ b/src/mongo/db/commands/geo_near_cmd.cpp
@@ -288,6 +288,8 @@ public:
         PlanSummaryStats summary;
         Explain::getSummaryStats(*exec, &summary);
         collection->infoCache()->notifyOfQuery(txn, summary.indexesUsed);
+        CurOp::get(txn)->debug().fromMultiPlanner = summary.fromMultiPlanner;
+        CurOp::get(txn)->debug().replanned = summary.replanned;
 
         stats.appendNumber("nscanned", summary.totalKeysExamined);
         stats.appendNumber("objectsLoaded", summary.totalDocsExamined);
diff --git a/src/mongo/db/commands/group_cmd.cpp b/src/mongo/db/commands/group_cmd.cpp
index c279fa458a1..2bbc9515f5f 100644
--- a/src/mongo/db/commands/group_cmd.cpp
+++ b/src/mongo/db/commands/group_cmd.cpp
@@ -172,6 +172,8 @@ private:
         if (coll) {
             coll->infoCache()->notifyOfQuery(txn, summaryStats.indexesUsed);
         }
+        CurOp::get(txn)->debug().fromMultiPlanner = summaryStats.fromMultiPlanner;
+        CurOp::get(txn)->debug().replanned = summaryStats.replanned;
 
         invariant(STAGE_GROUP == planExecutor->getRootStage()->stageType());
         GroupStage* groupStage = static_cast<GroupStage*>(planExecutor->getRootStage());
diff --git a/src/mongo/db/commands/mr.cpp b/src/mongo/db/commands/mr.cpp
index ee7ece9ac9a..ebf1f075cd4 100644
--- a/src/mongo/db/commands/mr.cpp
+++ b/src/mongo/db/commands/mr.cpp
@@ -1490,6 +1490,8 @@ public:
                 PlanSummaryStats stats;
                 Explain::getSummaryStats(*exec, &stats);
                 coll->infoCache()->notifyOfQuery(txn, stats.indexesUsed);
+                CurOp::get(txn)->debug().fromMultiPlanner = stats.fromMultiPlanner;
+                CurOp::get(txn)->debug().replanned = stats.replanned;
             }
             pm.finished();
 
diff --git a/src/mongo/db/commands/pipeline_command.cpp b/src/mongo/db/commands/pipeline_command.cpp
index d1dbfb582ea..fc3537d1a49 100644
--- a/src/mongo/db/commands/pipeline_command.cpp
+++ b/src/mongo/db/commands/pipeline_command.cpp
@@ -235,6 +235,8 @@ public:
                 PlanSummaryStats stats;
                 Explain::getSummaryStats(*input, &stats);
                 collection->infoCache()->notifyOfQuery(txn, stats.indexesUsed);
+                CurOp::get(txn)->debug().fromMultiPlanner = stats.fromMultiPlanner;
+                CurOp::get(txn)->debug().replanned = stats.replanned;
             }
 
             // Create the PlanExecutor which returns results from the pipeline. The WorkingSet
diff --git a/src/mongo/db/commands/write_commands/batch_executor.cpp b/src/mongo/db/commands/write_commands/batch_executor.cpp
index c2abf7c6968..c8d2a3e83b2 100644
--- a/src/mongo/db/commands/write_commands/batch_executor.cpp
+++ b/src/mongo/db/commands/write_commands/batch_executor.cpp
@@ -1351,6 +1351,8 @@ static void multiRemove(OperationContext* txn,
             PlanSummaryStats summary;
             Explain::getSummaryStats(*exec, &summary);
             collection->infoCache()->notifyOfQuery(txn, summary.indexesUsed);
+            CurOp::get(txn)->debug().fromMultiPlanner = summary.fromMultiPlanner;
+            CurOp::get(txn)->debug().replanned = summary.replanned;
 
             if (repl::ReplClientInfo::forClient(client).getLastOp() != lastOpAtOperationStart) {
                 // If this operation has already generated a new lastOp, don't bother setting it
diff --git a/src/mongo/db/curop.cpp b/src/mongo/db/curop.cpp
index 0ba60bc86c3..93c86f6bed8 100644
--- a/src/mongo/db/curop.cpp
+++ b/src/mongo/db/curop.cpp
@@ -513,6 +513,8 @@ string OpDebug::report(const CurOp& curop, const SingleThreadedLockStats& lockSt
     OPDEBUG_TOSTRING_HELP(docsExamined);
     OPDEBUG_TOSTRING_HELP_BOOL(idhack);
     OPDEBUG_TOSTRING_HELP_BOOL(hasSortStage);
+    OPDEBUG_TOSTRING_HELP_BOOL(fromMultiPlanner);
+    OPDEBUG_TOSTRING_HELP_BOOL(replanned);
     OPDEBUG_TOSTRING_HELP(nmoved);
     OPDEBUG_TOSTRING_HELP(nMatched);
     OPDEBUG_TOSTRING_HELP(nModified);
@@ -629,6 +631,8 @@ void OpDebug::append(const CurOp& curop,
     OPDEBUG_APPEND_NUMBER(docsExamined);
     OPDEBUG_APPEND_BOOL(idhack);
     OPDEBUG_APPEND_BOOL(hasSortStage);
+    OPDEBUG_APPEND_BOOL(fromMultiPlanner);
+    OPDEBUG_APPEND_BOOL(replanned);
     OPDEBUG_APPEND_BOOL(moved);
     OPDEBUG_APPEND_NUMBER(nmoved);
     OPDEBUG_APPEND_NUMBER(nMatched);
diff --git a/src/mongo/db/curop.h b/src/mongo/db/curop.h
index 74632b85534..7e57c80e0dc 100644
--- a/src/mongo/db/curop.h
+++ b/src/mongo/db/curop.h
@@ -169,6 +169,13 @@ public:
 
     bool hasSortStage{false};  // true if the query plan involves an in-memory sort
 
+    // True if the plan came from the multi-planner (not from the plan cache and not a query with a
+    // single solution).
+    bool fromMultiPlanner{false};
+
+    // True if a replan was triggered during the execution of this operation.
+    bool replanned{false};
+
     long long nMatched{-1};   // number of records that match the query
     long long nModified{-1};  // number of records written (no no-ops)
     long long nmoved{-1};     // updates resulted in a move (moves are expensive)
diff --git a/src/mongo/db/exec/cached_plan.cpp b/src/mongo/db/exec/cached_plan.cpp
index 45977701402..6b3f43e3ff1 100644
--- a/src/mongo/db/exec/cached_plan.cpp
+++ b/src/mongo/db/exec/cached_plan.cpp
@@ -201,6 +201,8 @@ Status CachedPlanStage::replan(PlanYieldPolicy* yieldPolicy, bool shouldCache) {
     _ws->clear();
     _children.clear();
 
+    _specificStats.replanned = true;
+
     // Use the query planning module to plan the whole query.
     std::vector<QuerySolution*> rawSolutions;
     Status status = QueryPlanner::plan(*_canonicalQuery, _plannerParams, &rawSolutions);
diff --git a/src/mongo/db/exec/plan_stats.h b/src/mongo/db/exec/plan_stats.h
index 7587aa47da8..9be40b37a07 100644
--- a/src/mongo/db/exec/plan_stats.h
+++ b/src/mongo/db/exec/plan_stats.h
@@ -183,11 +183,13 @@ struct AndSortedStats : public SpecificStats {
 };
 
 struct CachedPlanStats : public SpecificStats {
-    CachedPlanStats() {}
+    CachedPlanStats() : replanned(false) {}
 
     SpecificStats* clone() const final {
         return new CachedPlanStats(*this);
     }
+
+    bool replanned;
 };
 
 struct CollectionScanStats : public SpecificStats {
diff --git a/src/mongo/db/exec/update.cpp b/src/mongo/db/exec/update.cpp
index c35c41687f8..835c24f6381 100644
--- a/src/mongo/db/exec/update.cpp
+++ b/src/mongo/db/exec/update.cpp
@@ -1036,6 +1036,8 @@ void UpdateStage::fillOutOpDebug(const UpdateStats* updateStats,
     // Copy summary information about the plan into OpDebug.
     opDebug->keysExamined = summaryStats->totalKeysExamined;
     opDebug->docsExamined = summaryStats->totalDocsExamined;
+    opDebug->fromMultiPlanner = summaryStats->fromMultiPlanner;
+    opDebug->replanned = summaryStats->replanned;
 }
 
 UpdateResult UpdateStage::makeUpdateResult(const UpdateStats* updateStats) {
diff --git a/src/mongo/db/instance.cpp b/src/mongo/db/instance.cpp
index 496590d05b0..65cfef9429a 100644
--- a/src/mongo/db/instance.cpp
+++ b/src/mongo/db/instance.cpp
@@ -860,6 +860,8 @@ void receivedDelete(OperationContext* txn, const NamespaceString& nsString, Mess
             PlanSummaryStats summary;
             Explain::getSummaryStats(*exec, &summary);
             collection->infoCache()->notifyOfQuery(txn, summary.indexesUsed);
+            op.debug().fromMultiPlanner = summary.fromMultiPlanner;
+            op.debug().replanned = summary.replanned;
 
             if (repl::ReplClientInfo::forClient(client).getLastOp() != lastOpAtOperationStart) {
                 // If this operation has already generated a new lastOp, don't bother setting it
diff --git a/src/mongo/db/query/explain.cpp b/src/mongo/db/query/explain.cpp
index 02b023f9021..bbe8ddb9a5c 100644
--- a/src/mongo/db/query/explain.cpp
+++ b/src/mongo/db/query/explain.cpp
@@ -31,6 +31,7 @@
 #include "mongo/db/query/explain.h"
 
 #include "mongo/base/owned_pointer_vector.h"
+#include "mongo/db/exec/cached_plan.h"
 #include "mongo/db/exec/count_scan.h"
 #include "mongo/db/exec/distinct_scan.h"
 #include "mongo/db/exec/idhack.h"
@@ -72,14 +73,15 @@ void flattenStatsTree(const PlanStageStats* root, vector<const PlanStageStats*>*
  * MultiPlanStage is encountered, only add the best plan and its children to 'flattened'.
  */
 void flattenExecTree(const PlanStage* root, vector<const PlanStage*>* flattened) {
+    flattened->push_back(root);
+
     if (root->stageType() == STAGE_MULTI_PLAN) {
-        // Only add the winning stage from a MultiPlanStage.
+        // Only add the winning plan from a MultiPlanStage.
         auto mps = static_cast<const MultiPlanStage*>(root);
         const PlanStage* winningStage = mps->getChildren()[mps->bestPlanIdx()].get();
         return flattenExecTree(winningStage, flattened);
     }
 
-    flattened->push_back(root);
     const auto& children = root->getChildren();
     for (size_t i = 0; i < children.size(); ++i) {
         flattenExecTree(children[i].get(), flattened);
@@ -785,6 +787,13 @@ void Explain::getSummaryStats(const PlanExecutor& exec, PlanSummaryStats* statsO
             const NearStats* nearStats =
                 static_cast<const NearStats*>(nearStage->getSpecificStats());
             statsOut->indexesUsed.insert(nearStats->indexName);
+        } else if (STAGE_CACHED_PLAN == stages[i]->stageType()) {
+            const CachedPlanStage* cachedPlan = static_cast<const CachedPlanStage*>(stages[i]);
+            const CachedPlanStats* cachedStats =
+                static_cast<const CachedPlanStats*>(cachedPlan->getSpecificStats());
+            statsOut->replanned = cachedStats->replanned;
+        } else if (STAGE_MULTI_PLAN == stages[i]->stageType()) {
+            statsOut->fromMultiPlanner = true;
         }
     }
 }
diff --git a/src/mongo/db/query/explain.h b/src/mongo/db/query/explain.h
index 069d89d7cb4..fa4a06f3a87 100644
--- a/src/mongo/db/query/explain.h
+++ b/src/mongo/db/query/explain.h
@@ -46,34 +46,33 @@ class OperationContext;
  * other non-explain debug mechanisms may want to collect.
  */
 struct PlanSummaryStats {
-    PlanSummaryStats()
-        : nReturned(0),
-          totalKeysExamined(0),
-          totalDocsExamined(0),
-          executionTimeMillis(0),
-          isIdhack(false),
-          hasSortStage(false) {}
-
     // The number of results returned by the plan.
-    size_t nReturned;
+    size_t nReturned = 0U;
 
     // The total number of index keys examined by the plan.
-    size_t totalKeysExamined;
+    size_t totalKeysExamined = 0U;
 
     // The total number of documents examined by the plan.
-    size_t totalDocsExamined;
+    size_t totalDocsExamined = 0U;
 
     // The number of milliseconds spent inside the root stage's work() method.
-    long long executionTimeMillis;
+    long long executionTimeMillis = 0;
 
     // Did this plan use the fast path for key-value retrievals on the _id index?
-    bool isIdhack;
+    bool isIdhack = false;
 
     // Did this plan use an in-memory sort stage?
-    bool hasSortStage;
+    bool hasSortStage = false;
 
     // The names of each index used by the plan.
     std::set<std::string> indexesUsed;
+
+    // Was this plan a result of using the MultiPlanStage to select a winner among several
+    // candidates?
+    bool fromMultiPlanner = false;
+
+    // Was a replan triggered during the execution of this query?
+    bool replanned = false;
 };
 
 /**
diff --git a/src/mongo/db/query/find.cpp b/src/mongo/db/query/find.cpp
index b6450108372..cd4677343df 100644
--- a/src/mongo/db/query/find.cpp
+++ b/src/mongo/db/query/find.cpp
@@ -157,6 +157,8 @@ void endQueryOp(OperationContext* txn,
     curop->debug().keysExamined = summaryStats.totalKeysExamined;
     curop->debug().docsExamined = summaryStats.totalDocsExamined;
     curop->debug().idhack = summaryStats.isIdhack;
+    curop->debug().fromMultiPlanner = summaryStats.fromMultiPlanner;
+    curop->debug().replanned = summaryStats.replanned;
 
     if (collection) {
         collection->infoCache()->notifyOfQuery(txn, summaryStats.indexesUsed);