[SERVER-31078] Query planning is very slow during multiplanning when result set is empty Created: 13/Sep/17  Updated: 24/Jul/23

Status: Backlog
Project: Core Server
Component/s: None
Affects Version/s: None
Fix Version/s: None

Type: Improvement Priority: Major - P3
Reporter: Mark Callaghan Assignee: Backlog - Query Optimization
Resolution: Unresolved Votes: 1
Labels: None
Remaining Estimate: Not Specified
Time Spent: Not Specified
Original Estimate: Not Specified

Issue Links:
Related
related to SERVER-62981 Make SBE multi-planner's trial period... Closed
related to SERVER-63642 Add serverStatus metrics to measure m... Closed
is related to SERVER-24312 Mongo Query Taking Lot of Time Select... Closed
is related to SERVER-24396 Progressive elimination of candidate ... Backlog
Assigned Teams:
Query Optimization
Sprint: Query 2017-10-23
Participants:
Case:

 Description   

The MultiPlanStage picks the best plan by "working all the plans, stopping when a plan hits EOF or returns some fixed number of results". But if the query returns no results, this stopping condition can take a very long time and we've essentially done a full index scan before returning.


Original Description

I updated my insert benchmark scripts to do full index scans for the PK and secondary indexes. The queries are written to do full index scans and find no rows. There are two loops for the timing – first run the query, second explain the query. Two of the queries have slow explains – queries 2 and 4. From the explain output they each have rejected plans that use a sort.

For the output below, there are 4 queries. Query 1 is the PK scan and then queries 2, 3 and 4 are full scans of each secondary index. The data below is from a setup with 10M docs in one collection. This is the time to scan each index:

Query 1 scan 9 seconds for 1 tables and explain 0
Query 2 scan 24 seconds for 1 tables and explain 0
Query 3 scan 21 seconds for 1 tables and explain 0
Query 4 scan 26 seconds for 1 tables and explain 0

And this is the time to do the explain for each query. Note that the explain for queries 2 and 4 takes more than 10 seconds. For the queries with slow explains there were rejected plans that use a sort.

Query 1 scan 0 seconds for 1 tables and explain 1
Query 2 scan 12 seconds for 1 tables and explain 1
Query 3 scan 0 seconds for 1 tables and explain 1
Query 4 scan 11 seconds for 1 tables and explain 1

A sample command line for repeating the test using https://github.com/mdcallag/mytools/blob/master/bench/ibench/iql.sh
bash iql.sh mongo "" /usr/bin/mongo /data/m/mo sdb 1 1 yes no no 0 no 10000000

Planner output for the slow explain with query 2. There is an index on (price,customerid) and the query is:

db.pi1.find"'({ price : { $gte : 0 }, customerid : { $lt : 0 } }, { _id:0, price:1, customerid:1}).sort({price:1, customerid:1})

{
        "queryPlanner" : {
                "plannerVersion" : 1,
                "namespace" : "ib.pi1",
                "indexFilterSet" : false,
                "parsedQuery" : {
                        "$and" : [
                                {
                                        "customerid" : {
                                                "$lt" : 0
                                        }
                                },
                                {
                                        "price" : {
                                                "$gte" : 0
                                        }
                                }
                        ]
                },
                "winningPlan" : {
                        "stage" : "PROJECTION",
                        "transformBy" : {
                                "_id" : 0,
                                "price" : 1,
                                "customerid" : 1
                        },
                        "inputStage" : {
                                "stage" : "IXSCAN",
                                "keyPattern" : {
                                        "price" : 1,
                                        "customerid" : 1
                                },
                                "indexName" : "pc",
                                "isMultiKey" : false,
                                "multiKeyPaths" : {
                                        "price" : [ ],
                                        "customerid" : [ ]
                                },
                                "isUnique" : false,
                                "isSparse" : false,
                                "isPartial" : false,
                                "indexVersion" : 2,
                                "direction" : "forward",
                                "indexBounds" : {
                                        "price" : [
                                                "[0.0, inf.0]"
                                        ],
                                        "customerid" : [
                                                "[-inf.0, 0.0)"
                                        ]
                                }
                        }
                },
                "rejectedPlans" : [
                        {
                                "stage" : "PROJECTION",
                                "transformBy" : {
                                        "_id" : 0,
                                        "price" : 1,
                                        "customerid" : 1
                                },
                                "inputStage" : {
                                        "stage" : "SORT",
                                        "sortPattern" : {
                                                "price" : 1,
                                                "customerid" : 1
                                        },
                                        "inputStage" : {
                                                "stage" : "SORT_KEY_GENERATOR",
                                                "inputStage" : {
                                                        "stage" : "FETCH",
                                                        "inputStage" : {
                                                                "stage" : "IXSCAN",
                                                                "keyPattern" : {
                                                                        "price" : 1,
                                                                        "dateandtime" : 1,
                                                                        "customerid" : 1
                                                                },
                                                                "indexName" : "pdc",
                                                                "isMultiKey" : false,
                                                                "multiKeyPaths" : {
                                                                        "price" : [ ],
                                                                        "dateandtime" : [ ],
                                                                        "customerid" : [ ]
                                                                },
                                                                "isUnique" : false,
                                                                "isSparse" : false,
                                                                "isPartial" : false,
                                                                "indexVersion" : 2,
                                                                "direction" : "forward",
                                                                "indexBounds" : {
                                                                        "price" : [
                                                                                "[0.0, inf.0]"
                                                                        ],
                                                                        "dateandtime" : [
                                                                                "[MinKey, MaxKey]"
                                                                        ],
                                                                        "customerid" : [
                                                                                "[-inf.0, 0.0)"
                                                                        ]
                                                                }
                                                        }
                                                }
                                        }
                                }
                        }
                ]
        },
        "serverInfo" : {
                "host" : "nuc1",
                "port" : 27017,
                "version" : "3.4.6-1.7",
                "gitVersion" : "74b930309498503ee1c64d9a2526e45e2da464a2"
        },
        "ok" : 1
}



 Comments   
Comment by David Storch [ 08/Dec/17 ]

Thanks kyle.suarez. We've seen a couple cases like this before, e.g. SERVER-24312. Also, SERVER-24396 describes a behavior change which might help to mitigate this problem. We're going to leave this ticket open to track the problem, though I'm changing its fixVersion to "Backlog" in order to indicate that we don't plan to work on it in the near future.

Comment by Kyle Suarez [ 06/Nov/17 ]

Hi mdcallag,

Sorry for the delay in getting back to you. I can reproduce this behavior and it confirms our suspicions about the trial period for plan selection. I wrote my own script that roughly simulates your benchmark and populates a collection with 10000000 documents and builds two compound indexes:

setup.js

    const kNumDocuments = 10000000;
    const coll = db.getCollection("explainTooSlow");
 
    if (coll.count() != kNumDocuments) {
        Random.setRandomSeed();
 
        coll.drop();
        const bulk = coll.initializeUnorderedBulkOp();
        for (let i = 0; i < kNumDocuments; ++i) {
            bulk.insert({
                _id: NumberLong(i),
                price: i,
                dateAndTime: Timestamp(1000, i),
                customerId: Random.randInt(2000),
            });
        }
        assert.writeOK(bulk.execute());
    }
 
    assert.commandWorked(coll.createIndex({price: 1, customerId: 1}));
    assert.commandWorked(coll.createIndex({price: 1, dateAndTime: 1, customerId: 1}));

To get more accurate timing information on the plan selection trial period, I made the following modifications to the multiplanner:

diff --git a/src/mongo/db/exec/multi_plan.cpp b/src/mongo/db/exec/multi_plan.cpp
index 4b32b06ade..42d00f40b4 100644
--- a/src/mongo/db/exec/multi_plan.cpp
+++ b/src/mongo/db/exec/multi_plan.cpp
@@ -210,6 +210,7 @@ Status MultiPlanStage::pickBestPlan(PlanYieldPolicy* yieldPolicy) {
 
     // Work the plans, stopping when a plan hits EOF or returns some
     // fixed number of results.
+    _timer.reset();
     for (size_t ix = 0; ix < numWorks; ++ix) {
         bool moreToDo = workAllPlans(numResults, yieldPolicy);
         if (!moreToDo) {
@@ -217,6 +218,10 @@ Status MultiPlanStage::pickBestPlan(PlanYieldPolicy* yieldPolicy) {
         }
     }
 
+    auto micros = _timer.micros();
+    log() << "XXX: working all the plans took " << micros << " microseconds (" << (micros / 1000)
+          << " milliseconds)";
+
     if (_failure) {
         invariant(WorkingSet::INVALID_ID != _statusMemberId);
         WorkingSetMember* member = _candidates[0].ws->get(_statusMemberId);
diff --git a/src/mongo/db/exec/multi_plan.h b/src/mongo/db/exec/multi_plan.h
index 7ec6bad81d..0e8d094eb1 100644
--- a/src/mongo/db/exec/multi_plan.h
+++ b/src/mongo/db/exec/multi_plan.h
@@ -38,6 +38,7 @@
 #include "mongo/db/query/plan_yield_policy.h"
 #include "mongo/db/query/query_solution.h"
 #include "mongo/db/record_id.h"
+#include "mongo/util/timer.h"
 
 namespace mongo {
 
@@ -230,6 +231,8 @@ private:
 
     // Stats
     MultiPlanStats _specificStats;
+
+    Timer _timer;
 };
 
 }  // namespace mongo

A query with one expected result in the center of the data set is very fast and working all the plans takes about 326 microseconds. A query that returns zero results takes forever: 7057401 microseconds (7.056 seconds) to select the best plan, which is basically all of the round-trip time as measured by the JS shell script.

Thanks for the report; I've updated the description and am sending this to the Query Team to triage at the next planning meeting.

Regards,
Kyle

P.S. My full standalone repro script is here: https://gist.github.com/ksuarz/ace0a62ddb3da958efa44c3e5e779b15

Comment by Kyle Suarez [ 14/Sep/17 ]

Hi mdcallag, thanks for filing this; I'll be taking a look at it in the coming weeks.

david.storch believes that the query returns no results is significant. For such queries, the plan ranker is unable to determine which of its plans is the best because none of them return any results. This might lead to an extended trial period that aversely affects query timing. However, I'll have to take a deeper dive at the code to be sure.

Comment by Mark Callaghan [ 14/Sep/17 ]

Here is an example from Mongo 3.4.6 for mmapv1, WiredTiger and MongoRocks. For each engine there are 2 groups of 4 lines. The first (explain 0) has the number of seconds to run the query for each index (Query 1 is PK, Query 2, 3 & 4 are the secondary indexes). The second group (explain 1) has the number of seconds for the explain.

From below the explain for query 2 and query 4 take half as long as the query, and in the MongoRocks case that is about 4 minutes.

From mmapv1

Query 1 scan 22 seconds for 16 tables and explain 0
Query 2 scan 35 seconds for 16 tables and explain 0
Query 3 scan 31 seconds for 16 tables and explain 0
Query 4 scan 37 seconds for 16 tables and explain 0
 
Query 1 scan 0 seconds for 16 tables and explain 1
Query 2 scan 17 seconds for 16 tables and explain 1
Query 3 scan 0 seconds for 16 tables and explain 1
Query 4 scan 17 seconds for 16 tables and explain 1

From WiredTiger

Query 1 scan 40 seconds for 16 tables and explain 0
Query 2 scan 58 seconds for 16 tables and explain 0
Query 3 scan 43 seconds for 16 tables and explain 0
Query 4 scan 58 seconds for 16 tables and explain 0
Query 1 scan 0 seconds for 16 tables and explain 1
Query 2 scan 27 seconds for 16 tables and explain 1
Query 3 scan 0 seconds for 16 tables and explain 1
Query 4 scan 27 seconds for 16 tables and explain 1

From MongoRocks

Query 1 scan 86 seconds for 16 tables and explain 0
Query 2 scan 833 seconds for 16 tables and explain 0
Query 3 scan 534 seconds for 16 tables and explain 0
Query 4 scan 565 seconds for 16 tables and explain 0
 
Query 1 scan 0 seconds for 16 tables and explain 1
Query 2 scan 265 seconds for 16 tables and explain 1
Query 3 scan 0 seconds for 16 tables and explain 1
Query 4 scan 267 seconds for 16 tables and explain 1

Generated at Thu Feb 08 04:25:55 UTC 2024 using Jira 9.7.1#970001-sha1:2222b88b221c4928ef0de3161136cc90c8356a66.