プロファイルを使用してMongoDBで遅いクエリを分析する手順

      MongoDBでは、スロークエリが発生した場合、そのスロークエリのステートメントを取得し、最適化するにはどうすればよいのでしょうか。今日はこの作品からいくつかのインサイトをご覧ください。

01 スロークエリを集めるには？

    MongoDBでは通常、スローログを収集するプロファイルをオンにすることができ、現在のプロファイルの状態を表示するステートメントは次のとおりです。

test1:PRIMARY> db.getProfilingStatus()
{
        "was" : 2,
        "slowms" : 0,
        "sampleRate" : 1,
        "$gleStats" : {
                "lastOpTime" : Timestamp(0, 0),
                "electionId" : ObjectId("7fffffff0000000000000005")
        },
        "lastCommittedOpTime" : Timestamp(1619186976, 2),
        "$configServerState" : {
                "opTime" : {
                        "ts" : Timestamp(1619186976, 1),
                        "t" : NumberLong(2)
                }
        },
        "$clusterTime" : {
                "clusterTime" : Timestamp(1619186976, 2),
                "signature" : {
                        "hash" : BinData(0,"zvwFpgc0KFxieMpj7mBPdrOnonI="),
                        "keyId" : NumberLong("6904838687771590657")
                }
        },
        "operationTime" : Timestamp(1619186976, 2)
}

ここで、2つの重要なパラメータ、wasとslowmsを見ることができます。

は0であり、ステートメントが記録されないことを意味する。

was=1、これは実行にslowms以上かかったステートメントをログに記録することを意味します。

was=2: すべてのステートメントが記録される

slowms は発言の閾値を ms で表します。

上図の結果は、当インスタンスが収集したすべてのクエリ文を表しています。プロファイルが収集したクエリ文の結果は、管理者データベースのsystem.profileコレクションに格納され、以下の方法でアクセスすることが可能です。

test1:PRIMARY> use admin
switched to db admin

test1:PRIMARY> db.system.profile.find({'op':'query'},{'op':1,'ns':1,'millis':1,'ts':1})
{ "op" : "query", "ns" : "admin.system.users", "millis" : 0, "ts" : ISODate(" 2020-08-27T07:22:14.815Z") }
{ "op" : "query", "ns" : "admin.system.users", "millis" : 0, "ts" : ISODate(" 2020-08-27T07:22:15.139Z") }
{ "op" : "query", "ns" : "admin.system.users", "millis" : 0, "ts" : ISODate(" 2020-08-27T07:22:15.141Z") }
{ "op" : "query", "ns" : "admin.system.users", "millis" : 0, "ts" : ISODate(" 2020-08-27T07:22:15.239Z") }
{ "op" : "query", "ns" : "admin.system.version", "millis" : 0, "ts" : ISODate(" "2020-08-27T07:22:16.155Z") }
{ "op" : "query", "ns" : "admin.system.version", "millis" : 0, "ts" : ISODate(& "2020-08-27T07:22:16.192Z") }
{ "op" : "query", "ns" : "admin.system.users", "millis" : 0, "ts" : ISODate(" 2020-08-27T07:22:16.225Z") }
{ "op" : "query", "ns" : "admin.system.users", "millis" : 0, "ts" : ISODate(" 2020-08-27T07:22:16.273Z") }
{ "op" : "query", "ns" : "admin.system.version", "millis" : 0, "ts" : ISODate(" quot;2020-08-27T07:22:16.276Z") }

02 system.profileスロークエリ収集分析

   管理者データベースのsystem.profileは、設定を超えたスロークエリの結果を固定で保持するコレクションです。その中にあるスロークエリの一つを見てみましょう。

    以下を使用して、データの一部を取得し、その中の重要なフィールドに注釈を付けます。

test1:PRIMARY> db.system.profile.findOne({'op':'query'})
{
        "op" : "query", # operation type
        "ns" : "admin.system.users", # namespace
        "command" : {
                "find" : "system.users",
                "filter" : {
                        "_id" : "admin.root" # Fields to filter
                },
                "limit" : 1,
                "singleBatch" : true,
                "lsid" : {
                        "id" : UUID("a6034f5e-77c1-4b19-9669-60e1253edf4b")
                },
                "$readPreference" : {
                        "mode" : "secondaryPreferred"
                },
                "$db" : "admin"
        },
        "keysExamined" : 1, # number of indexes scanned
        "docsExamined" : 1, # Number of rows scanned
        "cursorExhausted" : true,  
        "numYield" : 0,
        "nreturned" : 1, # the number of rows of returned values
        "locks" : {
                xxxx # Lock information
        },
        "flowControl" : {

        },
        "storage" : {
        },
        "responseLength" : 647,
        "protocol" : "op_query",
        "millis" : 0, # The execution time of this query, because we set profilestatus to 0, so all operations are logged.
        "planSummary" : "IDHACK", # Query against _id
        "execStats" : { # Query execution status
                "

03 Slow query analysis tool ---explain
   Typically, we can use MongoDB's plain syntax to analyze the query performance of a statement, including information such as whether indexes are used, the number of rows scanned, etc. The basic usage of the plain syntax:
Postscript writing
db.system.profile.find({'op':'query'}).explain()
Pre-writing
db.system.profile.explain().find({'op':'query'})

where plain can be placed after or before the query statement, and the find syntax can be update, remove, or insert
The output of the explain syntax is divided into 3 different levels of detail, as follows.
The three clarity modes, the higher the clarity, the more complete the output, and by default the queryPlanner.
1. queryPlanner mode (default)


db.products.explain().count( { quantity: { $gt: 50 } } )
2. executionStats schema


db.products.explain("executionStats").count( { quantity: { $gt: 50 } } )
{ 
3. allPlansExecution schema


db.products.explain("allPlansExecution").count( { quantity: { $gt: 50 } } )
{ 
Of these, the allPlansExecution pattern outputs the most information.
The following is the output of an explain syntax, with the following SQL for the query.
db.getCollection('files').find(
{"cTime":{
           "$gte":ISODate("2021-04-18"),
           "$lt":ISODate("2021-04-19")
       }}).limit(1000).explain("allPlansExecution")

The output is as follows.
{
        "queryPlanner" : { # Represents the execution plan of the query
                "plannerVersion" : 1, # version number
                "namespace" : "fs.files", # The namespace of the query, i.e. the collection name
                "indexFilterSet" : false, # whether index filtering is used, note that it does not determine whether indexing is used
                "parsedQuery" : { # The query syntax parse tree
                        "$and" : [
                                {
                                        "cTime" : {
                                                "$lt" : ISODate("2021-04-19T00:00:00Z")
                                        }
                                },
                                {
                                        "cTime" : {
                                                "$gte" : ISODate("2021-04-18T00:00:00Z")
                                        }
                                }
                        ]
                },
                "winningPlan" : { # The final selected query plan
                        "stage" : "LIMIT", # The stage of the query, very important, described in detail below
                        "limitAmount" : 1000, # The limit value of the query result
                        "inputStage" : {
                                "stage" : "FETCH",
                                "inputStage" : {
                                        "stage" : "IXSCAN", # stands for index scan
                                        "keyPattern" : {
                                                "cTime" : 1
                                        },
                                        "indexName" : "cTime_1", # index name
                                        "isMultiKey" : false, # The following 4 fields are all index type analysis
                                        "isUnique" : false,
                                        "isSparse" : false,
                                        "isPartial" : false,
                                        "indexVersion" : 1,
                                        "direction" : "forward",
                                        "indexBounds" : {
                                                "cTime" : [
                                                        "[new Date(1618704000000), new Date(1618790400000))"
                                                ]
                                        }
                                }
                        }
                },
                "rejectedPlans" : [ ] # Candidate unselected query plans
        },
        "serverInfo" : {
                "host" : "xxxx",
                "port" : 24999,
                "version" : "3.2.8",
                "gitVersion" : "ed70e33130c977bda0024c125b56d159573dbaf0"
        },
        "ok" : 1
}

First, explain the stages of the STAGE.
COLLSCAN - full table scan
IXSCAN --- index scan
FETCH --- retrieve documents based on indexes
SHARD_MERGE---Merge the results of slicing
IDHACK --- Query against id
LIMIT --- Execute the LIMIT
After understanding these stages of stage, we can see that a query is parsed layer by layer, so we can see that the stage field is nested. the execution plan in winningPlan also follows a layer by layer sequence: the
1. execute the innermost index scan (IXSCAN) first.
2, and then execute the outside FETCH, according to the index to get the document
3, the implementation of the last step of the limit, take the specified number of results returned to the client
The above is the detail of MongoDB profile analysis slow query example, more information about MongoDB profile analysis slow query please pay attention to other related articles of the Codedevlib!

Postscript writing
db.system.profile.find({'op':'query'}).explain()
Pre-writing
db.system.profile.explain().find({'op':'query'})