MongoDB查詢優化：從 10s 到 10ms

本文是我前同事付秋雷最近遇到到一個關於MongoDB執行計劃選擇的問題，非常有意思，在探索源碼之後，他將整個問題搞明白並整理分享出來。付秋雷(他的博客）曾是 Tair（阿裏內部用得非常廣泛的KV存儲係統）的核心開發成員，目前就職於蘑菇街。

背景

蘇先生反饋線上某條查詢很慢（10+ seconds），語句相當於

db.myColl.find({app:"my_app",requestTime:{$gte:1492502247000,$lt:1492588800000}}).sort({_id:-1}).limit(1)

myColl這個collection中的記錄內容類似於：

{ "_id" : ObjectId("58fd895359cb8757d493ce60"), "app" : "my_app", "eventId" : 141761066, "requestTime" : NumberLong("1493010771753"), "scene" : "scene01" }
{ "_id" : ObjectId("58fd895359cb8757d493ce52"), "app" : "my_app", "eventId" : 141761052, "requestTime" : NumberLong("1493010771528"), "scene" : "scene02" }
{ "_id" : ObjectId("58fd895359cb8757d493ce36"), "app" : "my_app", "eventId" : 141761024, "requestTime" : NumberLong("1493010771348"), "scene" : "scene03" }
{ "_id" : ObjectId("58fd895359cb8757d493ce31"), "app" : "my_app", "eventId" : 141761019, "requestTime" : NumberLong("1493010771303"), "scene" : "scene01" }
{ "_id" : ObjectId("58fd895359cb8757d493ce2d"), "app" : "my_app", "eventId" : 141761015, "requestTime" : NumberLong("1493010771257"), "scene" : "scene01" }
{ "_id" : ObjectId("58fd895259cb8757d493ce10"), "app" : "my_app", "eventId" : 141760986, "requestTime" : NumberLong("1493010770866"), "scene" : "scene01" }
{ "_id" : ObjectId("58fd895259cb8757d493ce09"), "app" : "my_app", "eventId" : 141760979, "requestTime" : NumberLong("1493010770757"), "scene" : "scene01" }
{ "_id" : ObjectId("58fd895259cb8757d493ce02"), "app" : "my_app", "eventId" : 141760972, "requestTime" : NumberLong("1493010770614"), "scene" : "scene03" }
{ "_id" : ObjectId("58fd895259cb8757d493cdf1"), "app" : "my_app", "eventId" : 141760957, "requestTime" : NumberLong("1493010770342"), "scene" : "scene02" }
{ "_id" : ObjectId("58fd895259cb8757d493cde6"), "app" : "my_app", "eventId" : 141760946, "requestTime" : NumberLong("1493010770258"), "scene" : "scene01" }

相關的索引有：

[
    {
        "v" : 1,
        "key" : {
            "_id" : 1
        },
        "name" : "_id_",
        "ns" : "myDatabase.myColl"
    },
    {
        "v" : 1,
        "key" : {
            "responseTime" : -1
        },
        "name" : "idx_responseTime_-1",
        "ns" : "myDatabase.myColl"
    },
    {
        "v" : 1,
        "key" : {
            "app" : 1,
            "scene" : 1,
            "eventId" : -1,
            "requestTime" : -1
        },
        "name" : "idx_app_1_scene_1_eventId_-1_requestTime_-1",
        "ns" : "myDatabase.myColl"
    }
]

慢查詢就是在myColl中查找符合[1492502247000, 1492588800000)這個時間範圍的所有記錄，**以下描述中稱這條查詢為bad query**。

如果去掉$lt:1492588800000這個約束條件，查找[1492502247000, +∞)這個時間範圍，就會很快（milliseconds）。

db.myColl.find({app:"my_app",requestTime:{$gte:1492502247000}}).sort({_id:-1}).limit(1)

以下描述中稱這條查詢為good query。

問題來了：

[問題A] 這兩條查詢都是走的什麼索引呢？導致執行時間相差如此之大
[問題B] 如果兩條查詢選取的索引不同，為什麼會有這個不同呢，這兩條查詢長得還是挺像的
[問題C] 如果bad query選取和good query一樣的索引，是否還會有一樣的問題呢

`問題A`

這兩條查詢都是走的什麼索引呢？導致執行時間相差如此之大

和Mysql一樣，Mongodb也提供了explain語句，可以獲取query語句的查詢計劃（queryPlanner）、以及執行過程中的統計信息（executionStats）。

違和發散：Cassandra中也是有類似的功能，Hbase中目前是沒有看到的。

在mongo shell中的使用方法是在query語句後麵加上.explain('executionStats')，對於上麵的good query，對應的explain語句為：

db.myColl.find({app:"my_app",requestTime:{$gte:1492502247000}}).sort({_id:-1}).limit(1).explain('executionStats')

good query的explain語句的執行結果如下，無關細節用...省略：

{
    "queryPlanner" : {
        "plannerVersion" : 1,
        "namespace" : "myDatabase.myColl",
        "indexFilterSet" : false,
        "parsedQuery" : ...
        "winningPlan" : {
            "stage" : "LIMIT",
            "limitAmount" : 1,
            "inputStage" : {
                "stage" : "FETCH",
                "filter" : ...,
                "inputStage" : {
                    "stage" : "IXSCAN",
                    "keyPattern" : {
                        "_id" : 1
                    },
                    "indexName" : "_id_",
                    ...
                    "direction" : "backward",
                    "indexBounds" : {
                        "_id" : [
                            "[MaxKey, MinKey]"
                        ]
                    }
                }
            }
        },
        "rejectedPlans" : ...,
    },
    "executionStats" : {
        "executionSuccess" : true,
        "nReturned" : 1,
        "executionTimeMillis" : 0,
        "totalKeysExamined" : 8,
        "totalDocsExamined" : 8,
        "executionStages" : {
            "stage" : "LIMIT",
            ...
            "inputStage" : {
                "stage" : "FETCH",
                ...
                "inputStage" : {
                    "stage" : "IXSCAN",
                    ...
                    "direction" : "backward",
                    "indexBounds" : {
                        "_id" : [
                            "[MaxKey, MinKey]"
                        ]
                    },
                    "keysExamined" : 8,
                    ...
                }
            }
        }
    },
    "serverInfo" : ...,
    "ok" : 1
}

結果分為四部分：queryPlanner、executionStats、serverInfo、ok，僅關注queryPlanner、executionStats這兩部分。

executionStats就是執行queryPlanner.winningPlan這個計劃時的統計信息，可以從indexBounds看到good query在索引掃描（IXSCAN）階段，**使用的索引是_id主鍵索引**。從IXSCAN這個階段的keysExamined統計可以解釋為什麼good query執行的這麼快，隻掃描了8條數據。

同樣使用explain語句看看bad query使用的是什麼索引：

{
    "queryPlanner" : {
        ...
        "winningPlan" : {
            "stage" : "SORT",
            ...
            "inputStage" : {
                "stage" : "SORT_KEY_GENERATOR",
                "inputStage" : {
                    "stage" : "FETCH",
                    "inputStage" : {
                        "stage" : "IXSCAN",
                        "keyPattern" : {
                            "app" : 1,
                            "scene" : 1,
                            "eventId" : -1,
                            "requestTime" : -1
                        },
                        "indexName" : "idx_app_1_scene_1_eventId_-1_requestTime_-1",
                        ...
                        "direction" : "forward",
                        "indexBounds" : {
                            "app" : [
                                "[\"my_app\", \"my_app\"]"
                            ],
                            "scene" : [
                                "[MinKey, MaxKey]"
                            ],
                            "eventId" : [
                                "[MaxKey, MinKey]"
                            ],
                            "requestTime" : [
                                "(1492588800000.0, 1492502247000.0]"
                            ]
                        }
                    }
                }
            }
        },
        "rejectedPlans" : ...,
    },
    "executionStats" : {
        "executionSuccess" : true,
        "nReturned" : 1,
        "executionTimeMillis" : 56414,
        "totalKeysExamined" : 3124535,
        "totalDocsExamined" : 275157,
        "executionStages" : {
            "stage" : "SORT",
            ...
            "inputStage" : {
                "stage" : "SORT_KEY_GENERATOR",
                ...
                "inputStage" : {
                    "stage" : "FETCH",
                    ...
                    "inputStage" : {
                        "stage" : "IXSCAN",
                        ...
                        "direction" : "forward",
                        "indexBounds" : {
                            "app" : [
                                "[\"my_app\", \"my_app\"]"
                            ],
                            "scene" : [
                                "[MinKey, MaxKey]"
                            ],
                            "eventId" : [
                                "[MaxKey, MinKey]"
                            ],
                            "requestTime" : [
                                "(1492588800000.0, 1492502247000.0]"
                            ]
                        },
                        "keysExamined" : 3124535,
                        ...
                    }
                }
            }
        }
    },
    "serverInfo" : ...,
    "ok" : 1
}

可以看到**bad query使用的索引是一個複合索引（Compound Indexes），確實和good query使用的索引不一樣**。同樣，從IXSCAN這個階段的keysExamined統計可以看到掃描了3124535條數據，所以執行時間會很長。

`問題B`

如果兩條查詢選取的索引不同，為什麼會有這個不同呢，這兩條查詢長得還是挺像的

Mongodb是如何為查詢選取認為合適的索引的呢？

粗略來說，會先選幾個候選的查詢計劃，然後會為這些查詢計劃按照某個規則來打分，分數最高的查詢計劃就是合適的查詢計劃，這個查詢計劃裏麵使用的索引就是認為合適的索引。

好，粗略地說完了，現在細致一點說（還是那句話：沒有代碼的解釋都是耍流氓，以下所有的代碼都是基於mongodb-3.2.10）。

先看一個棧：

mongo::PlanRanker::scoreTree
mongo::PlanRanker::pickBestPlan
mongo::MultiPlanStage::pickBestPlan
mongo::PlanExecutor::pickBestPlan
mongo::PlanExecutor::make
mongo::PlanExecutor::make
mongo::getExecutor
mongo::getExecutorFind
mongo::FindCmd::explain

這是使用lldb來調試mongod時，在mongo::PlanRanker::scoreTree（代碼位於src/mongo/db/query/plan_ranker.cpp）處設置斷點打印出來的棧。

scoreTree裏麵就是計算每個查詢計劃的得分的：

    // We start all scores at 1.  Our "no plan selected" score is 0 and we want all plans to
    // be greater than that.
    double baseScore = 1;

    // How many "units of work" did the plan perform. Each call to work(...)
    // counts as one unit.
    size_t workUnits = stats->common.works;

    // How much did a plan produce?
    // Range: [0, 1]
    double productivity =
        static_cast<double>(stats->common.advanced) / static_cast<double>(workUnits);

    ...

    double tieBreakers = noFetchBonus + noSortBonus + noIxisectBonus;
    double score = baseScore + productivity + tieBreakers;

scoreTree並沒有執行查詢，隻是根據已有的PlanStageStats* stats來進行計算。那麼，是什麼時候執行查詢來獲取查詢計劃的PlanStageStats* stats的呢？

在mongo::MultiPlanStage::pickBestPlan（代碼位於src/mongo/db/exec/multi_plan.cpp）中，會調用workAllPlans來執行所有的查詢計劃，最多會調用numWorks次：

    size_t numWorks = getTrialPeriodWorks(getOpCtx(), _collection);
    size_t numResults = getTrialPeriodNumToReturn(*_query);

    // Work the plans, stopping when a plan hits EOF or returns some
    // fixed number of results.
    for (size_t ix = 0; ix < numWorks; ++ix) {
        bool moreToDo = workAllPlans(numResults, yieldPolicy);
        if (!moreToDo) {
            break;
        }
    }

`問題C`

如果bad query選取和good query一樣的索引，是否還會有一樣的問題呢

Mongodb查詢時，可以借助於hint命令強製選取某一條索引來進行查詢，比如上述的bad query加上.hint({_id:1})，就可以強製使用主鍵索引：

db.myColl.find({app:"my_app",requestTime:{$gte:1492502247000,$lt:1492588800000}}).sort({_id:-1}).limit(1).hint({_id:1})

然而，即使是這樣，查詢還是很慢，依然加上.explain('executionStats')看一下執行情況，解答問題A時已經對explain的結果做了些解釋，所以這次著重看IXSCAN階段的keysExamined：

{
...
        "executionStages" : {
            "stage" : "LIMIT",
            ...
            "inputStage" : {
                "stage" : "FETCH",
                "filter" : {
                    "$and" : [
                        {
                            "app" : {
                                "$eq" : "my_app"
                            }
                        },
                        {
                            "requestTime" : {
                                "$lt" : 1492588800000
                            }
                        },
                        {
                            "requestTime" : {
                                "$gte" : 1492502247000
                            }
                        }
                    ]
                },
                "nReturned" : 1,
                ...
                "inputStage" : {
                    "stage" : "IXSCAN",
                    ...
                    "nReturned" : 32862524,
                    ...
                    "keysExamined" : 32862524,
                    ...
...
}

掃描了32862524條記錄，依然很慢。這個現象比較好解釋了，從executionStats.executionStages可以看到，加了hint的查詢經曆了LIMIT => FETCH => IXSCAN 這幾個階段，IXSCAN這個階段返回了32862524條記錄，被FETCH階段過濾隻剩下一條，所以有32862523條無效掃描，為什麼會有這麼多無效掃描呢？

這個和業務邏輯是相關的，requestTime時間戳是隨時間增長的，主鍵_id也可以認為隨時間增長的，所以按照主鍵索引倒序來，最開始被掃描的是最新的記錄，最新的記錄是滿足"requestTime" : {"$gte" : 1492502247000}這個條件的，所以good query隻需要滿足"app" : {"$eq" : "my_app"}就會很快返回；

然而bad query的約束條件"requestTime" : {"$gte" : 1492502247000, "$lt" : 1492588800000}中的"$lt" : 1492588800000是無法被滿足的，**必須要把所有比1492588800000這個時間戳新的記錄都掃描完了之後才會返回**。

蘇先生提出了完美的解決方案：不使用_id來排序，而是使用request_time來進行排序。這樣就會使用"requestTime" : -1這條索引，隻需要進行"app" : {"$eq" : "my_app"}的過濾，也是milliseconds時間內完成查詢。

總結

搭建有效的線下調試環境是重現、解決問題的重要手段，例如之前重現zk問題時使用salt快速搭建本地集群
維護開源產品不了解源碼，或者沒有找到看的有效入口，是很被動的，缺少定位解決問題的根本手段

參考

感謝林青大神在排查過程中提供的關鍵幫助。

最後更新：2017-04-28 23:21:44

MongoDB查詢優化：從 10s 到 10ms

背景

`問題A`

`問題B`

`問題C`

總結

參考

上一篇：大數據開發—常見問題（1）

下一篇：數夢工場重新定義混合雲

相關內容

熱門內容

最新內容

MongoDB查詢優化：從 10s 到 10ms

背景

問題A

問題B

問題C

總結

參考

上一篇： 大數據開發—常見問題（1）

下一篇： 數夢工場重新定義混合雲

相關內容

熱門內容

最新內容

`問題A`

`問題B`

`問題C`

上一篇：大數據開發—常見問題（1）

下一篇：數夢工場重新定義混合雲