SERVER-40805 Indicate reason for replanning

10 files changed, 89 insertions, 25 deletions

diff --git a/jstests/core/profile_find.js b/jstests/core/profile_find.js
index 98834a9fc31..30dec540f82 100644
--- a/jstests/core/profile_find.js
+++ b/jstests/core/profile_find.js
@@ -115,8 +115,11 @@
     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);
+    assert(profileObj.hasOwnProperty('replanReason'));
+    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/));
+    assert.eq(profileObj.appName, "MongoDB Shell");
 
     //
     // 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..57f0598b353
--- /dev/null
+++ b/jstests/noPassthrough/plan_cache_replan_sort.js
@@ -0,0 +1,48 @@
+/**
+ * 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(db.runCommand({insert: coll.getName(), documents: 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);
+    const winningPlan = cachedPlans[0];
+    assert.eq("SORT", winningPlan.reason.stats.stage);
+
+    // 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());
+    assert.eq(profileObj.replanned, true);
+    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.");
+
+    MongoRunner.stopMongod(conn);
+}());
diff --git a/src/mongo/db/curop.cpp b/src/mongo/db/curop.cpp
index a58c9c5b020..4e39242b04c 100644
--- a/src/mongo/db/curop.cpp
+++ b/src/mongo/db/curop.cpp
@@ -492,7 +492,11 @@ string OpDebug::report(Client* client,
     OPDEBUG_TOSTRING_HELP(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(nMatched);
     OPDEBUG_TOSTRING_HELP(nModified);
     OPDEBUG_TOSTRING_HELP(ninserted);
@@ -582,7 +586,11 @@ void OpDebug::append(const CurOp& curop,
     OPDEBUG_APPEND_NUMBER(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_NUMBER(nMatched);
     OPDEBUG_APPEND_NUMBER(nModified);
     OPDEBUG_APPEND_NUMBER(ninserted);
@@ -640,7 +648,7 @@ void OpDebug::setPlanSummaryMetrics(const PlanSummaryStats& planSummaryStats) {
     docsExamined = planSummaryStats.totalDocsExamined;
     hasSortStage = planSummaryStats.hasSortStage;
     fromMultiPlanner = planSummaryStats.fromMultiPlanner;
-    replanned = planSummaryStats.replanned;
+    replanReason = planSummaryStats.replanReason;
 }
 
 }  // namespace mongo
diff --git a/src/mongo/db/curop.h b/src/mongo/db/curop.h
index 4cae06075a5..c35fc2b952a 100644
--- a/src/mongo/db/curop.h
+++ b/src/mongo/db/curop.h
@@ -102,7 +102,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;
 
     long long nMatched{-1};   // number of records that match the query
     long long nModified{-1};  // number of records written (no no-ops)
diff --git a/src/mongo/db/exec/cached_plan.cpp b/src/mongo/db/exec/cached_plan.cpp
index 2139b307416..f0d69aca483 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.
     std::vector<QuerySolution*> rawSolutions;
diff --git a/src/mongo/db/exec/cached_plan.h b/src/mongo/db/exec/cached_plan.h
index a3fd804c7a9..5316f440e1f 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 8e194484497..73604962829 100644
--- a/src/mongo/db/query/explain.cpp
+++ b/src/mongo/db/query/explain.cpp
@@ -896,7 +896,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.