【mongoDB】mongoDB 慢日志解读

2024-06-27T11:09:45.649+0800 I COMMAND [conn390533] command testDB.T_test command: find { find: "T_test", filter: { _id: "667cd79b554c7031d6b6b9e8" }, limit: 1, shardVersion: [ Timestamp 22528000|1, ObjectId('5d6785e8e65179d5d4e78e46') ] } planSummary: IDHACK keysExamined:0 docsExamined:0 cursorExhausted:1 numYields:0 nreturned:0 reslen:199 locks:{ Global: { acquireCount: { r: 2 }, acquireWaitCount: { r: 1 }, timeAcquiringMicros: { r: 56311835 } }, Database: { acquireCount: { r: 1 } }, Collection: { acquireCount: { r: 1 } } } protocol:op_command 56322ms

根据提供的MongoDB日志，我们来详细解析一下：

日志解析

日志中的关键部分如下：

2024-06-27T11:09:45.649+0800 I COMMAND [conn390533] command testDB.T_test command: find { find: "T_test", filter: { _id: "667cd79b554c7031d6b6b9e8" }, limit: 1, shardVersion: [ Timestamp 22528000|1, ObjectId('5d6785e8e65179d5d4e78e46') ] } planSummary: IDHACK keysExamined:0 docsExamined:0 cursorExhausted:1 numYields:0 nreturned:0 reslen:199 locks:{ Global: { acquireCount: { r: 2 }, acquireWaitCount: { r: 1 }, timeAcquiringMicros: { r: 56311835 } }, Database: { acquireCount: { r: 1 } }, Collection: { acquireCount: { r: 1 } } } protocol:op_command 56322ms

1. 时间戳和连接信息:

   • 时间戳: 2024-06-27T11:09:45.649+0800
   • 连接信息: [conn390533]

2. 命令信息:

   • 命令类型: command
   • 数据库和集合: testDB.T_test
   • 命令内容: command: find { find: "T_test", filter: { _id: "667cd79b554c7031d6b6b9e8" }, limit: 1, shardVersion: [ Timestamp 22528000|1, ObjectId('5d6785e8e65179d5d4e78e46') ] }

3. 执行计划和统计信息:

   • 执行计划总结: planSummary: IDHACK
   • 键检查数: keysExamined:0
   • 文档检查数: docsExamined:0
   • 游标耗尽: cursorExhausted:1
   • 返回数量: nreturned:0
   • 结果长度: reslen:199

4. 锁和协议信息:

   • 锁信息:
     • 全局锁: { Global: { acquireCount: { r: 2 }, acquireWaitCount: { r: 1 }, timeAcquiringMicros: { r: 56311835 } }
     • 数据库锁: { acquireCount: { r: 1 } }
     • 集合锁: { acquireCount: { r: 1 } }
   • 协议: protocol:op_command
   • 执行时间: 56322ms (56.322秒)

分析查询慢的原因

1. 索引使用情况:

   • 日志中显示 IDHACK 的执行计划总结，表示MongoDB使用了 _id 索引的快速查找机制。但是，keysExamined 和 docsExamined 都为0，这意味着没有检查索引键或者文档，理论上来说这是一个非常快速的查询操作。然而，实际执行时间却非常长（56秒）。

2. 锁情况:

   • 日志显示了大量的锁等待和获取信息。全局锁的获取次数为2，且等待次数为1，耗时达到了56311835微秒（约56秒）。这可能意味着在执行查询时，受到了其他并发操作的阻塞或竞争，导致查询执行变得非常缓慢。

3. 其他可能的原因:

   • 集群状态: 如果是分片集群，还需要关注分片版本和分片状态是否正常。
   • 服务器资源: 查询过程中是否存在服务器资源不足的情况，如CPU负载高、内存不足等。
   • 网络延迟: 数据库访问的网络延迟也可能影响查询性能。

总结

尽管 _id 字段有索引且查询理论上应该很快，但实际查询时间非常长可能是由于全局锁的等待和获取次数过多导致的阻塞情况。建议进一步分析数据库的并发使用情况，查看是否可以优化锁的竞争，或者考虑调整服务器资源配置以改善查询性能。

testDB.T_test 的 "_id" 字段有索引，为什么查询会这么慢？

2024-06-27T11:09:45.649+0800 I COMMAND [conn390533] command testDB.T_test command: find { find: "T_test", filter: { _id: "667cd79b554c7031d6b6b9e8" }, limit: 1, shardVersion: [ Timestamp 22528000|1, ObjectId('5d6785e8e65179d5d4e78e46') ] } planSummary: IDHACK keysExamined:0 docsExamined:0 cursorExhausted:1 numYields:0 nreturned:0 reslen:199 locks:{ Global: { acquireCount: { r: 2 }, acquireWaitCount: { r: 1 }, timeAcquiringMicros: { r: 56311835 } }, Database: { acquireCount: { r: 1 } }, Collection: { acquireCount: { r: 1 } } } protocol:op_command 56322ms

日志解析

日志中的关键部分如下：

2024-06-27T11:09:45.649+0800 I COMMAND [conn390533] command testDB.T_test command: find { find: "T_test", filter: { _id: "667cd79b554c7031d6b6b9e8" }, limit: 1, shardVersion: [ Timestamp 22528000|1, ObjectId('5d6785e8e65179d5d4e78e46') ] } planSummary: IDHACK keysExamined:0 docsExamined:0 cursorExhausted:1 numYields:0 nreturned:0 reslen:199 locks:{ Global: { acquireCount: { r: 2 }, acquireWaitCount: { r: 1 }, timeAcquiringMicros: { r: 56311835 } }, Database: { acquireCount: { r: 1 } }, Collection: { acquireCount: { r: 1 } } } protocol:op_command 56322ms

1. 时间戳和连接信息:

   • 时间戳: 2024-06-27T11:09:45.649+0800
   • 连接信息: [conn390533]

2. 命令信息:

   • 命令类型: command
   • 数据库和集合: testDB.T_test
   • 命令内容: command: find { find: "T_test", filter: { _id: "667cd79b554c7031d6b6b9e8" }, limit: 1, shardVersion: [ Timestamp 22528000|1, ObjectId('5d6785e8e65179d5d4e78e46') ] }

3. 执行计划和统计信息:

   • 执行计划总结: planSummary: IDHACK
   • 键检查数: keysExamined:0
   • 文档检查数: docsExamined:0
   • 游标耗尽: cursorExhausted:1
   • 返回数量: nreturned:0
   • 结果长度: reslen:199

4. 锁和协议信息:

   • 锁信息:
     • 全局锁: { Global: { acquireCount: { r: 2 }, acquireWaitCount: { r: 1 }, timeAcquiringMicros: { r: 56311835 } }
     • 数据库锁: { acquireCount: { r: 1 } }
     • 集合锁: { acquireCount: { r: 1 } }
   • 协议: protocol:op_command
   • 执行时间: 56322ms (56.322秒)

分析查询慢的原因

1. 索引使用情况:

   • 日志中显示 IDHACK 的执行计划总结，表示MongoDB使用了 _id 索引的快速查找机制。但是，keysExamined 和 docsExamined 都为0，这意味着没有检查索引键或者文档，理论上来说这是一个非常快速的查询操作。然而，实际执行时间却非常长（56秒）。

2. 锁情况:

   • 日志显示了大量的锁等待和获取信息。全局锁的获取次数为2，且等待次数为1，耗时达到了56311835微秒（约56秒）。这可能意味着在执行查询时，受到了其他并发操作的阻塞或竞争，导致查询执行变得非常缓慢。

3. 其他可能的原因:

   • 集群状态: 如果是分片集群，还需要关注分片版本和分片状态是否正常。
   • 服务器资源: 查询过程中是否存在服务器资源不足的情况，如CPU负载高、内存不足等。
   • 网络延迟: 数据库访问的网络延迟也可能影响查询性能。

总结

尽管 _id 字段有索引且查询理论上应该很快，但实际查询时间非常长可能是由于全局锁的等待和获取次数过多导致的阻塞情况。建议进一步分析数据库的并发使用情况，查看是否可以优化锁的竞争，或者考虑调整服务器资源配置以改善查询性能。