summaryrefslogtreecommitdiff
diff options
context:
space:
mode:
Diffstat
-rw-r--r--jstests/core/profile_find.js9
-rw-r--r--jstests/noPassthrough/plan_cache_replan_sort.js49
-rw-r--r--src/mongo/db/curop.cpp14
-rw-r--r--src/mongo/db/curop.h2
-rw-r--r--src/mongo/db/exec/cached_plan.cpp19
-rw-r--r--src/mongo/db/exec/cached_plan.h2
-rw-r--r--src/mongo/db/exec/plan_stats.h4
-rw-r--r--src/mongo/db/query/explain.cpp2
-rw-r--r--src/mongo/db/query/plan_summary_stats.h2
-rw-r--r--src/mongo/db/sorter/sorter.cpp14
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.
View Lorry Controller Status