From e3acf12767b9192e24a3b2bbd810e6b11a965ed6 Mon Sep 17 00:00:00 2001 From: David Percy Date: Mon, 6 Jan 2020 19:41:50 +0000 Subject: SERVER-40805 Indicate reason for replanning --- jstests/core/profile_find.js | 7 ++-- jstests/noPassthrough/plan_cache_replan_sort.js | 48 +++++++++++++++++++++++++ src/mongo/db/curop.cpp | 14 ++++++-- src/mongo/db/curop.h | 2 +- src/mongo/db/exec/cached_plan.cpp | 19 +++++++--- src/mongo/db/exec/cached_plan.h | 2 +- src/mongo/db/exec/plan_stats.h | 4 +-- src/mongo/db/query/explain.cpp | 2 +- src/mongo/db/query/plan_summary_stats.h | 2 +- src/mongo/db/sorter/sorter.cpp | 14 +++----- 10 files changed, 89 insertions(+), 25 deletions(-) create mode 100644 jstests/noPassthrough/plan_cache_replan_sort.js 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 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 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 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(stages[i]); const CachedPlanStats* cachedStats = static_cast(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 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. -- cgit v1.2.1