mongodb的慢查询-CFANZ编程社区

####################################

首先，慢查询日志是针对数据库级别的，咱们设置的时候，要先use 数据库，再开启，一定先确定某个数据库再db.setProfilingLevel(2,500)

# 获取超过0.5秒的慢查询：
db.system.profile.find({millis:{$gt:500}})

# 获取最新的慢查询：
db.system.profile.find().sort({$natural:-1})

一、获取慢查询配置：

性能分析器Profiling级别参数：

0值：关闭性能分析器，不收集任何数据。mongod总是将时间长于slowOpThresholdMs阀值的操作写入到日志。这是默认的性能分析器级别。
1值：只收集慢操作性能分析数据.默认慢操作是那些操作时间大于100毫米的操作。
2值：收集所有数据库操作的性能分析数据。

##############################################################
db.getProfilingStatus()

db.setProfilingLevel(1,500)

db.setProfilingLevel(1,1000)  # 相当于1s

db.setProfilingLevel(0)  #关闭慢查询

db.system.profile.drop()  # 删除慢查询集合

db.createCollection( "system.profile", { capped: true, size:10000000 } )  # 重建慢查询集合

db.setProfilingLevel(2,500)   #开启慢查询和配置慢查询阈值

具体例子如下：

glc-test:PRIMARY> db.getProfilingStatus()
{
        "was" : 0,
        "slowms" : 500,
        "ratelimit" : 1,
        "sampleRate" : 1,
        "operationTime" : Timestamp(1606295083, 1),
        "$clusterTime" : {
                "clusterTime" : Timestamp(1606295083, 1),
                "signature" : {
                        "hash" : BinData(0,"21NKX80GE0q/yEV5AJII6XAwctQ="),
                        "keyId" : NumberLong("6856584343653974019")
                }
        }
}
glc-test:PRIMARY> db.getProfilingLevel()
0
glc-test:PRIMARY> db.setProfilingLevel(1,500)
{
        "was" : 0,
        "slowms" : 500,
        "ratelimit" : 1,
        "sampleRate" : 1,
        "ok" : 1,
        "operationTime" : Timestamp(1606295103, 1),
        "$clusterTime" : {
                "clusterTime" : Timestamp(1606295103, 1),
                "signature" : {
                        "hash" : BinData(0,"9m9XwRHgd18Ik2AouRUIvh2DFLg="),
                        "keyId" : NumberLong("6856584343653974019")
                }
        }
}
glc-test:PRIMARY>

二、删除慢查询集合：

db.setProfilingLevel(0)

db.system.profile.drop()

具体例子如下：

glc-test:PRIMARY> db.getProfilingStatus()
{
        "was" : 1,
        "slowms" : 500,
        "ratelimit" : 1,
        "sampleRate" : 1,
        "operationTime" : Timestamp(1606294533, 1),
        "$clusterTime" : {
                "clusterTime" : Timestamp(1606294533, 1),
                "signature" : {
                        "hash" : BinData(0,"UDIIGdRByffSd7zBXbKOocNHVf4="),
                        "keyId" : NumberLong("6856584343653974019")
                }
        }
}
glc-test:PRIMARY> db.system.profile.drop()
2020-11-25T16:55:53.233+0800 E QUERY    [js] Error: drop failed: {
        "operationTime" : Timestamp(1606294543, 1),
        "ok" : 0,
        "errmsg" : "turn off profiling before dropping system.profile collection",
        "code" : 20,
        "codeName" : "IllegalOperation",
        "$clusterTime" : {
                "clusterTime" : Timestamp(1606294543, 1),
                "signature" : {
                        "hash" : BinData(0,"IS5isA2D6B9TAnEsaW/SFsfwe+0="),
                        "keyId" : NumberLong("6856584343653974019")
                }
        }
} :
_getErrorWithCode@src/mongo/shell/utils.js:25:13
DBCollection.prototype.drop@src/mongo/shell/collection.js:707:1
@(shell):1:1



glc-test:PRIMARY> db.setProfilingLevel(0)
{
        "was" : 1,
        "slowms" : 500,
        "ratelimit" : 1,
        "sampleRate" : 1,
        "ok" : 1,
        "operationTime" : Timestamp(1606294563, 1),
        "$clusterTime" : {
                "clusterTime" : Timestamp(1606294563, 1),
                "signature" : {
                        "hash" : BinData(0,"NT7TdpDLfjzC37lDMtINsmJvVQ0="),
                        "keyId" : NumberLong("6856584343653974019")
                }
        }
}
glc-test:PRIMARY> db.system.profile.drop()
true
glc-test:PRIMARY>

三、创建慢查询集合：

db.createCollection("system.profile", {size: 40000000, capped: true})

具体例子如下：

glc-test:PRIMARY> show tables;
glc
glc-test:PRIMARY> db.createCollection("system.profile", {size: 40000000, capped: true})
{
        "ok" : 1,
        "operationTime" : Timestamp(1606294983, 1),
        "$clusterTime" : {
                "clusterTime" : Timestamp(1606294983, 1),
                "signature" : {
                        "hash" : BinData(0,"vXiMidZUy7pXCg2t8Zvj4zgsO4E="),
                        "keyId" : NumberLong("6856584343653974019")
                }
        }
}
glc-test:PRIMARY> show tables;
glc
system.profile
glc-test:PRIMARY>

解读 db.system.profile.find().pretty()：

# "op" : "query",表示操作的类型，代表了该慢日志的种类是什么，是查询、插入、更新、删除还是其他。主要有：

insert
query
update
remove
getmore
command

# "ns" : "igoodful.log" ：表示该慢日志是哪个库下的哪个集合所对应的慢日志。

# system.profile.nreturned  ：该操作最终返回文档的数量；

# system.profile.responseLength ：结果返回的大小，单位为bytes，该值如果过大，则需考虑limit()等方式减少输出结果；

# system.profile.millis ：该操作从开始到结束耗时多少，单位为毫秒；

# system.profile.execStats ：包含了一些该操作的统计信息，只有query类型的才会显示此项，包含查询操作的执行统计信息的文档。对于其他操作，该值为空文档。

# system.profile.execStats.stage ：查询类型

COLLSCAN 用于收集扫描
IXSCAN 用于扫描索引键
FETCH 用于检索文件

# system.profile.ts ：该操作执行时的时间

# system.profile.locks：全局、库、表的锁使用情况

# system.profile.PlanSummary：索引使用情况，有：

collscan —— 全表扫描
ixscan —— 索引扫描
idhack —— 使用了默认的_id索引
fetch —— 根据索引去检索某一个文档
shard_metge —— 将各个分片的返回数据进行聚合
sharding_filter —— 通过mongos对分片数据进行查询

# system.profile.numYield：让出锁

# system.profile.client ：哪个客户端发起的该操作，并显示出该客户端的ip或hostname

# system.profile.client ：

{
        "op" : "query",
        "ns" : "igoodful.log",
        "command" : {
                "find" : "log",
                "filter" : {

                },
                "sort" : {
                        "t" : -1
                },
                "limit" : 1,
                "lsid" : {
                        "id" : UUID("832477ad-a7e6-4bfc-9f2b-4b04538d77f3")
                },
                "$clusterTime" : {
                        "clusterTime" : Timestamp(1611211743, 4),
                        "signature" : {
                                "hash" : BinData(0,"bWjbtJwf0mD9oImjMxc1JTIElOk="),
                                "keyId" : NumberLong("6908999957030633474")
                        }
                },
                "$db" : "igoodful",
                "$readPreference" : {
                        "mode" : "primary"
                }
        },
        "keysExamined" : 0,
        "docsExamined" : 173829,
        "hasSortStage" : true,
        "cursorExhausted" : true,
        "numYield" : 1358,
        "nreturned" : 1,
        "locks" : {
                "Global" : {
                        "acquireCount" : {
                                "r" : NumberLong(1361)
                        }
                },
                "Database" : {
                        "acquireCount" : {
                                "r" : NumberLong(1359)
                        }
                },
                "Collection" : {
                        "acquireCount" : {
                                "r" : NumberLong(1359)
                        }
                }
        },
        "storage" : {

        },
        "responseLength" : 1005,
        "protocol" : "op_msg",
        "millis" : 669,
        "rateLimit" : 1,
        "planSummary" : "COLLSCAN",
        "execStats" : {
                "stage" : "SORT",
                "nReturned" : 1,
                "executionTimeMillisEstimate" : 77,
                "works" : 173834,
                "advanced" : 1,
                "needTime" : 173832,
                "needYield" : 0,
                "saveState" : 1358,
                "restoreState" : 1358,
                "isEOF" : 1,
                "invalidates" : 0,
                "sortPattern" : {
                        "t" : -1
                },
                "memUsage" : 782,
                "memLimit" : 33554432,
                "limitAmount" : 1,
                "inputStage" : {
                        "stage" : "SORT_KEY_GENERATOR",
                        "nReturned" : 173829,
                        "executionTimeMillisEstimate" : 35,
                        "works" : 173832,
                        "advanced" : 173829,
                        "needTime" : 2,
                        "needYield" : 0,
                        "saveState" : 1358,
                        "restoreState" : 1358,
                        "isEOF" : 1,
                        "invalidates" : 0,
                        "inputStage" : {
                                "stage" : "COLLSCAN",
                                "nReturned" : 173829,
                                "executionTimeMillisEstimate" : 15,
                                "works" : 173831,
                                "advanced" : 173829,
                                "needTime" : 1,
                                "needYield" : 0,
                                "saveState" : 1358,
                                "restoreState" : 1358,
                                "isEOF" : 1,
                                "invalidates" : 0,
                                "direction" : "forward",
                                "docsExamined" : 173829
                        }
                }
        },
        "ts" : ISODate("2021-01-21T06:49:04.415Z"),
        "client" : "10.10.10.11",
        "allUsers" : [
                {
                        "user" : "igoodful_wr",
                        "db" : "admin"
                }
        ],
        "user" : "igoodful_wr@admin"
}

{
    "timestamp": "Thu Apr  2 07:51:50.985"  // 日期和时间, ISO8601格式
    "severityLevel": "I"  // 日志级别 I代表info的意思，其他的还有F,E,W,D等
    "components": "COMMAND"  //组件类别，不同组件打印出的日志带不同的标签，便于日志分类
    "namespace": "animal.MongoUser_58"  //查询的命名空间，即<databse.collection>
    "operation": "find" //操作类别，可能是[find,insert,update,remove,getmore,command]
    "command": { find: "MongoUser_58", filter: { $and: [ { lld: { $gte: 18351 } }, { fc: { $lt: 120 } }, { _id: { $nin: [1244093274 ] } }, 
{ $or: [ { rc: { $exists: false } }, { rc: { $lte: 1835400100 } } ] }, { lv: { $gte: 69 } }, { lv: { $lte: 99 } }, 
{ cc: { $in: [ 440512, 440513, 440514, 440500, 440515, 440511, 440523, 440507 ] } } ] }, limit: 30 } //具体的操作命令细节
    "planSummary": "IXSCAN { lv: -1 }", // 命令执行计划的简要说明，当前使用了 lv 这个字段的索引。如果是全表扫描，则是COLLSCAN
    "keysExamined": 20856, // 该项表明为了找出最终结果MongoDB搜索了索引中的多少个key
    "docsExamined": 20856, // 该项表明为了找出最终结果MongoDB搜索了多少个文档
    "cursorExhausted": 1, // 该项表明本次查询中游标耗尽的次数
    "keyUpdates":0,  // 该项表名有多少个index key在该操作中被更改，更改索引键也会有少量的性能消耗，因为数据库不单单要删除旧Key，还要插入新的Key到B-Tree索引中
    "writeConflicts":0, // 写冲突发生的数量，例如update一个正在被别的update操作的文档
    "numYields":6801, // 为了让别的操作完成而屈服的次数，一般发生在需要访问的数据尚未被完全读取到内存中，MongoDB会优先完成在内存中的操作
    "nreturned":0, // 该操作最终返回文档的数量
    "reslen":110, // 结果返回的大小，单位为bytes，该值如果过大，则需考虑limit()等方式减少输出结果
    "locks": { // 在操作中产生的锁，锁的种类有多种，如下
        Global: { acquireCount: { r: 13604 } },   //具体每一种锁请求锁的次数
        Database: { acquireCount: { r: 6802 } }, 
        Collection: { acquireCount: { r: 6802 } } 
    },
    "protocol": "op_command", //  消息的协议
    "millis" : 69132, // 从 MongoDB 操作开始到结束耗费的时间，单位为ms
}

解读db.currentOp()：

#################################################