MongoDB 慢日志字段解析

原创

phoenix、

修改于 2021-01-06 17:15:37

4.7K0

修改于 2021-01-06 17:15:37

文章被收录于专栏：MongoDB 学习 MongoDB 学习MongoDB 学习

导语：最近很多人咨询MongoDB慢日志相关的问题，其中就有不少如何理解慢日志中具体字段含义的问题。本文尝试给出一个慢日志示例及对应的解析，希望能帮助到大家。

慢查询日志范例

"Thu Apr  2 07:51:50.985 I COMMAND  [conn541] command animal.MongoUser_58 command: find { 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 } keysExamined:20856 docsExamined:20856 cursorExhausted:1 keyUpdates:0 writeConflicts:0 numYields:6801 nreturned:0 reslen:110 locks:{ Global: { acquireCount: { r: 13604 } }, Database: { acquireCount: { r: 6802 } }, Collection: { acquireCount: { r: 6802 } } } protocol:op_command 8938329ms"

慢查询日志解析备注

{
    "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
}

字段详解

PS: 只阐述部分，其他在上面的注释中已标注。

Severity Levels 严重级别

很常见的日志级别划分，比较好理解

级别	描述
F	Fatal
E	Error
W	Warning
I	Info，对应`verbosity level`为0
D	Debug，对应`verbosity level`大于0

Components 组件

在MongoDB中，不同组件输出的日志会带不同的tag，方便区分。包含以下：

ACCESS —— 访问控制相关，比如认证
COMMAND —— 数据库命令，CURD等
CONTROL —— 控制行为，比如初始化等
FTDC —— 诊断数据收集机制相关，比如服务器统计信息和状态信息
GEO —— 与解析地理空间形状相关，比如验证GeoJSON形状
INDEX —— 索引操作相关，比如创建索引
NETWORK —— 网络相关，比如链接的建立和断开
QUERY —— 查询相关，比如查询计划
REPL —— 副本集相关，包括初始化同步、副本集节点心跳、主从同步、回滚等
- ELECTION —— 副本集选举相关（属于REPL的子tag）
- INITSYNC —— 初始化同步相关（属于REPL的子tag）
- REPL_HB —— 副本集内节点心跳相关
- ROLLBACK —— rollback状态相关
SHARDING —— 分片行为相关，比如mongos的启动
STORAGE —— 存储相关，比如fsync
RECOVERY —— recovery状态相关
JOURNAL —— journal相关
TXN —— 多文档事务相关
其他

随带一提，可以通过配置文件和db.setLogLevel()命令来设置整体的以及每个组件的日志级别。

对于慢日志而言，这里都是COMMAND

operation 操作类别

主要有以下几种类型，很好理解：

find
insert
delete
replace
update
drop
rename
dropDatabase

慢查询的操作类别都是find；当然对于比较大的批量insert或者update，MongoDB也会在日志中记录相应的日志，其对应的操作类别就是insert/update了。

writeConflicts 写冲突次数

写是要加写锁的，如果写冲突次数很多，比如多个操作同时更新同一个文档，可能会导致该操作耗时较长，主要就消耗在写冲突这里了。

planSummary 执行计划

这里表示MongoDB是怎么去取数据的，有以下几种类型：

COLLSCAN —— 全表扫描
IXSCAN —— 索引扫描
IDHACK —— 使用了默认的_id索引
FETCH —— 根据索引去检索某一个文档
SHARD_METGE —— 将各个分片的返回数据进行聚合
SHARDING_FILTER —— 通过mongos对分片数据进行查询

正常情况下一般都是IXSCAN，如果遇到COLLSCAN导致的慢查询的话，可以考虑新建相应的索引来优化查询了。

该字段后面会输出具体使用的哪一个索引。有可能一个表有多个索引，当这里的索引不符合预期时，也应该考虑优化索引或者通过hint()来改造查询语句。

yield

翻译成中文是屈服的意思，其实就是让出锁的意思。通常，进行文档搜索的操作（查询、更新和删除）可交出锁。只有在其他操作列队等待该操作所持有的锁时，它才有可能交出自己的锁(即yield一次)。简单来说，如果没有其他操作处于等锁(waitingForLock)的状态，则该操作不会交出锁(yield)。