导语 ：最近很多人咨询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 严重级别

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

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 )。

locks

MongoDB中的锁主要有以下几种，存在于不同的维度（全局 global 、库 Database 、表 Collection ）：

示例中的都是 意向共享（IS）锁 。

该字段数值很大代表锁争抢比较严重，是影响慢查询的一个因素之一。

参考资料

mongodb log messages

mongodb lock

mongodb explain results