SERVER-40805 Indicate reason for replanning

10 files changed, 92 insertions, 25 deletions

diff --git a/jstests/core/profile_find.js b/jstests/core/profile_find.js
index 86ef0d66830..d0f6a34fc1c 100644
--- a/jstests/core/profile_find.js
+++ b/jstests/core/profile_find.js
@@ -115,8 +115,13 @@
     assert.neq(coll.findOne({a: 15, b: 10}), null);
     profileObj = getLatestProfilerEntry(testDB, profileEntryFilter);
 
-    assert.eq(profileObj.replanned, true, tojson(profileObj));
-    assert.eq(profileObj.appName, "MongoDB Shell", tojson(profileObj));
+    assert.eq(profileObj.replanned, true, profileObj);
+    assert(profileObj.hasOwnProperty('replanReason'), profileObj);
+    assert(
+        profileObj.replanReason.match(
+            /cached plan was less efficient than expected: expected trial execution to take [0-9]+ works but it took at least [0-9]+ works/),
+        profileObj);
+    assert.eq(profileObj.appName, "MongoDB Shell", profileObj);
 
     //
     // Confirm that query modifiers such as "hint" are in the profiler document.
diff --git a/jstests/noPassthrough/plan_cache_replan_sort.js b/jstests/noPassthrough/plan_cache_replan_sort.js
new file mode 100644
index 00000000000..59cc1c41fb8
--- /dev/null
+++ b/jstests/noPassthrough/plan_cache_replan_sort.js
@@ -0,0 +1,49 @@
+/**
+ * Test that when replanning happens due to blocking sort's memory limit, we include
+ * replanReason: "cached plan returned: ..." in the profiling data.
+ * @tags: [requires_profiling]
+ */
+(function() {
+    "use strict";
+
+    load("jstests/libs/profiler.js");
+
+    const conn = MongoRunner.runMongod({
+        // Disallow blocking sort, by setting the memory limit very low (1 byte).
+        setParameter: "internalQueryExecMaxBlockingSortBytes=1"
+    });
+    const db = conn.getDB("test");
+    const coll = db.plan_cache_replan_sort;
+    coll.drop();
+
+    // Ensure a plan with a sort stage gets cached.
+    assert.commandWorked(coll.createIndex({x: 1}));
+    assert.commandWorked(coll.createIndex({y: 1}));
+    const docs = Array.from({length: 20}, (_, i) => ({x: 7, y: i}));
+    assert.commandWorked(coll.insert(docs));
+    // { x: 5 } is very selective because it matches 0 documents, so the x index will win.
+    // This will succeed despite the low memory limit on sort, because the sort stage will see zero
+    // documents.
+    assert.eq(0, coll.find({x: 5}).sort({y: 1}).itcount());
+
+    const cachedPlans = coll.getPlanCache().getPlansByQuery({x: 5}, {}, {y: 1}).plans;
+    assert.lte(1, cachedPlans.length, cachedPlans);
+    const winningPlan = cachedPlans[0];
+    assert.eq("SORT", winningPlan.reason.stats.stage, cachedPlans);
+
+    // Assert we "replan", by running the same query with different parameters.
+    // This time the filter is not selective at all.
+    db.setProfilingLevel(2);
+    assert.eq(20, coll.find({x: 7}).sort({y: 1}).itcount());
+
+    const profileObj = getLatestProfilerEntry(db, {op: "query"});
+    assert.eq(profileObj.ns, coll.getFullName(), profileObj);
+    assert.eq(profileObj.replanned, true, profileObj);
+    assert.eq(
+        profileObj.replanReason,
+        "cached plan returned: OperationFailed: Sort operation used more than the maximum 1 bytes of " +
+            "RAM. Add an index, or specify a smaller limit.",
+        profileObj);
+
+    MongoRunner.stopMongod(conn);
+}());
diff --git a/src/mongo/db/curop.cpp b/src/mongo/db/curop.cpp
index abf36e8f0b4..f152ccd8d8a 100644
--- a/src/mongo/db/curop.cpp
+++ b/src/mongo/db/curop.cpp
@@ -597,7 +597,11 @@ string OpDebug::report(Client* client,
     OPDEBUG_TOSTRING_HELP_OPTIONAL("docsExamined", additiveMetrics.docsExamined);
     OPDEBUG_TOSTRING_HELP_BOOL(hasSortStage);
     OPDEBUG_TOSTRING_HELP_BOOL(fromMultiPlanner);
-    OPDEBUG_TOSTRING_HELP_BOOL(replanned);
+    if (replanReason) {
+        bool replanned = true;
+        OPDEBUG_TOSTRING_HELP_BOOL(replanned);
+        s << " replanReason:\"" << escape(redact(*replanReason)) << "\"";
+    }
     OPDEBUG_TOSTRING_HELP_OPTIONAL("nMatched", additiveMetrics.nMatched);
     OPDEBUG_TOSTRING_HELP_OPTIONAL("nModified", additiveMetrics.nModified);
     OPDEBUG_TOSTRING_HELP_OPTIONAL("ninserted", additiveMetrics.ninserted);
@@ -682,7 +686,11 @@ void OpDebug::append(const CurOp& curop,
     OPDEBUG_APPEND_OPTIONAL("docsExamined", additiveMetrics.docsExamined);
     OPDEBUG_APPEND_BOOL(hasSortStage);
     OPDEBUG_APPEND_BOOL(fromMultiPlanner);
-    OPDEBUG_APPEND_BOOL(replanned);
+    if (replanReason) {
+        bool replanned = true;
+        OPDEBUG_APPEND_BOOL(replanned);
+        b.append("replanReason", *replanReason);
+    }
     OPDEBUG_APPEND_OPTIONAL("nMatched", additiveMetrics.nMatched);
     OPDEBUG_APPEND_OPTIONAL("nModified", additiveMetrics.nModified);
     OPDEBUG_APPEND_OPTIONAL("ninserted", additiveMetrics.ninserted);
@@ -738,7 +746,7 @@ void OpDebug::setPlanSummaryMetrics(const PlanSummaryStats& planSummaryStats) {
     additiveMetrics.docsExamined = planSummaryStats.totalDocsExamined;
     hasSortStage = planSummaryStats.hasSortStage;
     fromMultiPlanner = planSummaryStats.fromMultiPlanner;
-    replanned = planSummaryStats.replanned;
+    replanReason = planSummaryStats.replanReason;
 }
 
 namespace {
diff --git a/src/mongo/db/curop.h b/src/mongo/db/curop.h
index b3b3a5a1506..15b6e30bab6 100644
--- a/src/mongo/db/curop.h
+++ b/src/mongo/db/curop.h
@@ -173,7 +173,7 @@ public:
     bool fromMultiPlanner{false};
 
     // True if a replan was triggered during the execution of this operation.
-    bool replanned{false};
+    boost::optional<std::string> replanReason;
 
     bool fastmodinsert{false};  // upsert of an $operation. builds a default object
     bool upsert{false};         // true if the update actually did an insert
diff --git a/src/mongo/db/exec/cached_plan.cpp b/src/mongo/db/exec/cached_plan.cpp
index 13f8cc7fdd1..8211d9ef475 100644
--- a/src/mongo/db/exec/cached_plan.cpp
+++ b/src/mongo/db/exec/cached_plan.cpp
@@ -147,7 +147,10 @@ Status CachedPlanStage::pickBestPlan(PlanYieldPolicy* yieldPolicy) {
                    << " status: " << redact(statusObj);
 
             const bool shouldCache = false;
-            return replan(yieldPolicy, shouldCache);
+            return replan(yieldPolicy,
+                          shouldCache,
+                          str::stream() << "cached plan returned: "
+                                        << WorkingSetCommon::toStatusString(statusObj));
         } else if (PlanStage::DEAD == state) {
             BSONObj statusObj;
             invariant(WorkingSet::INVALID_ID != id);
@@ -173,7 +176,15 @@ Status CachedPlanStage::pickBestPlan(PlanYieldPolicy* yieldPolicy) {
            << " plan summary before replan: " << Explain::getPlanSummary(child().get());
 
     const bool shouldCache = true;
-    return replan(yieldPolicy, shouldCache);
+    return replan(
+        yieldPolicy,
+        shouldCache,
+        str::stream()
+            << "cached plan was less efficient than expected: expected trial execution to take "
+            << _decisionWorks
+            << " works but it took at least "
+            << maxWorksBeforeReplan
+            << " works");
 }
 
 Status CachedPlanStage::tryYield(PlanYieldPolicy* yieldPolicy) {
@@ -194,13 +205,13 @@ Status CachedPlanStage::tryYield(PlanYieldPolicy* yieldPolicy) {
     return Status::OK();
 }
 
-Status CachedPlanStage::replan(PlanYieldPolicy* yieldPolicy, bool shouldCache) {
+Status CachedPlanStage::replan(PlanYieldPolicy* yieldPolicy, bool shouldCache, std::string reason) {
     // We're going to start over with a new plan. Clear out info from our old plan.
     _results.clear();
     _ws->clear();
     _children.clear();
 
-    _specificStats.replanned = true;
+    _specificStats.replanReason = std::move(reason);
 
     // Use the query planning module to plan the whole query.
     auto statusWithSolutions = QueryPlanner::plan(*_canonicalQuery, _plannerParams);
diff --git a/src/mongo/db/exec/cached_plan.h b/src/mongo/db/exec/cached_plan.h
index 4e7b8f5dafd..b05f7d834d1 100644
--- a/src/mongo/db/exec/cached_plan.h
+++ b/src/mongo/db/exec/cached_plan.h
@@ -107,7 +107,7 @@ private:
      *
      * We only write the result of re-planning to the plan cache if 'shouldCache' is true.
      */
-    Status replan(PlanYieldPolicy* yieldPolicy, bool shouldCache);
+    Status replan(PlanYieldPolicy* yieldPolicy, bool shouldCache, std::string reason);
 
     /**
      * May yield during the cached plan stage's trial period or replanning phases.
diff --git a/src/mongo/db/exec/plan_stats.h b/src/mongo/db/exec/plan_stats.h
index 13e74cc3d9b..18aab5c6af3 100644
--- a/src/mongo/db/exec/plan_stats.h
+++ b/src/mongo/db/exec/plan_stats.h
@@ -214,7 +214,7 @@ struct AndSortedStats : public SpecificStats {
 };
 
 struct CachedPlanStats : public SpecificStats {
-    CachedPlanStats() : replanned(false) {}
+    CachedPlanStats() = default;
 
     SpecificStats* clone() const final {
         return new CachedPlanStats(*this);
@@ -224,7 +224,7 @@ struct CachedPlanStats : public SpecificStats {
         return sizeof(*this);
     }
 
-    bool replanned;
+    boost::optional<std::string> replanReason;
 };
 
 struct CollectionScanStats : public SpecificStats {
diff --git a/src/mongo/db/query/explain.cpp b/src/mongo/db/query/explain.cpp
index ac8f29d0bf6..0627cd78912 100644
--- a/src/mongo/db/query/explain.cpp
+++ b/src/mongo/db/query/explain.cpp
@@ -978,7 +978,7 @@ void Explain::getSummaryStats(const PlanExecutor& exec, PlanSummaryStats* statsO
             const CachedPlanStage* cachedPlan = static_cast<const CachedPlanStage*>(stages[i]);
             const CachedPlanStats* cachedStats =
                 static_cast<const CachedPlanStats*>(cachedPlan->getSpecificStats());
-            statsOut->replanned = cachedStats->replanned;
+            statsOut->replanReason = cachedStats->replanReason;
         } else if (STAGE_MULTI_PLAN == stages[i]->stageType()) {
             statsOut->fromMultiPlanner = true;
         }
diff --git a/src/mongo/db/query/plan_summary_stats.h b/src/mongo/db/query/plan_summary_stats.h
index 0fdc9934b52..ada5719b2ac 100644
--- a/src/mongo/db/query/plan_summary_stats.h
+++ b/src/mongo/db/query/plan_summary_stats.h
@@ -62,7 +62,7 @@ struct PlanSummaryStats {
     bool fromMultiPlanner = false;
 
     // Was a replan triggered during the execution of this query?
-    bool replanned = false;
+    boost::optional<std::string> replanReason;
 };
 
 }  // namespace mongo
diff --git a/src/mongo/db/sorter/sorter.cpp b/src/mongo/db/sorter/sorter.cpp
index c3fb9a42e97..ea35c01db91 100644
--- a/src/mongo/db/sorter/sorter.cpp
+++ b/src/mongo/db/sorter/sorter.cpp
@@ -555,11 +555,8 @@ private:
             // elsewhere where extSortAllowed could possibly be false, this message will
             // need to be revisited.
             uasserted(16819,
-                      str::stream()
-                          << "Sort exceeded memory limit of "
-                          << _opts.maxMemoryUsageBytes
-                          << " bytes, but did not opt in to external sorting. Aborting operation."
-                          << " Pass allowDiskUse:true to opt in.");
+                      str::stream() << "Sort exceeded memory limit of " << _opts.maxMemoryUsageBytes
+                                    << " bytes, but did not opt in to external sorting.");
         }
 
         sort();
@@ -841,11 +838,8 @@ private:
             // elsewhere where extSortAllowed could possibly be false, this message will
             // need to be revisited.
             uasserted(16820,
-                      str::stream()
-                          << "Sort exceeded memory limit of "
-                          << _opts.maxMemoryUsageBytes
-                          << " bytes, but did not opt in to external sorting. Aborting operation."
-                          << " Pass allowDiskUse:true to opt in.");
+                      str::stream() << "Sort exceeded memory limit of " << _opts.maxMemoryUsageBytes
+                                    << " bytes, but did not opt in to external sorting.");
         }
 
         // We should check readOnly before getting here.