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 89383
慢查询日志解析备注
{ "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，对应 |
|
D |
Debug，对应 |
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 操作类别
主要有以下几种类型，很好理解：
findinsertdeletereplaceupdatedroprenamedropDatabase
慢查询的操作类别都是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)。
locks
MongoDB中的锁主要有以下几种，存在于不同的维度（全局global、库Database、表Collection）：
慢日志 锁.png示例中的都是意向共享（IS）锁。
该字段数值很大代表锁争抢比较严重，是影响慢查询的一个因素之一。
转自：https://cloud.tencent.com/developer/article/1711795
