【mongoDB】mongoDB 慢日志解读

2024-03-24T15:17:17.510+0800 I COMMAND [conn17354568] command testDB.T_Test command: find { find: "T_Test ", filter: { creator: "6408f24ad5dec672328f3e36", deleteStatus: 0, formCodeId: { $in: [ "8273ba51fe054901b73ee5fe42e57faf" ] } }, sort: { createTime: -1 }, limit: 20 } planSummary: IXSCAN { creator: 1, deleteStatus: 1, createTime: -1, formCodeId: 1 } keysExamined:528 docsExamined:20 cursorExhausted:1 numYields:12 nreturned:20 reslen:38504 locks:{ Global: { acquireCount: { r: 26 }, acquireWaitCount: { r: 9 }, timeAcquiringMicros: { r: 21117783 } }, Database: { acquireCount: { r: 13 } }, Collection: { acquireCount: { r: 13 } } } protocol:op_query 21658ms

2024-03-24T15:17:17.510+0800 I COMMAND  [conn17354568] command testDB.T_Test command: find { find: "T_Test ", filter: { creator: "6408f24ad5dec672328f3e36", deleteStatus: 0, formCodeId: { $in: [ "8273ba51fe054901b73ee5fe42e57faf" ] } }, sort: { createTime: -1 }, limit: 20 } planSummary: IXSCAN { creator: 1, deleteStatus: 1, createTime: -1, formCodeId: 1 } keysExamined:528 docsExamined:20 cursorExhausted:1 numYields:12 nreturned:20 reslen:38504 locks:{ Global: { acquireCount: { r: 26 }, acquireWaitCount: { r: 9 }, timeAcquiringMicros: { r: 21117783 } }, Database: { acquireCount: { r: 13 } }, Collection: { acquireCount: { r: 13 } } } protocol:op_query 21658ms

这条MongoDB日志描述了一个查询操作的执行情况，让我们逐步解读和分析：

1. 时间戳和级别:

   • 时间戳: 2024-03-24T15:17:17.510+0800
   • 级别: I COMMAND，指示这是一个普通的命令操作。

2. 连接信息:

   • [conn17354568] 表示连接的编号，每个客户端连接MongoDB时会分配一个唯一的连接ID。

3. 执行的命令:

   • command testDB.T_Test command: find { find: "T_Test", ... }，表明执行了一个find命令，查询了testDB数据库中的T_Test集合。

4. 查询条件和选项:

   • { creator: "6408f24ad5dec672328f3e36", deleteStatus: 0, formCodeId: { $in: [ "8273ba51fe054901b73ee5fe42e57faf" ] } }，说明了查询的过滤条件，包括creator字段、deleteStatus字段和formCodeId字段的值。

5. 查询计划和性能统计:

   • planSummary: IXSCAN { creator: 1, deleteStatus: 1, createTime: -1, formCodeId: 1 }，表示使用了索引扫描来执行查询，索引包括了creator、deleteStatus、createTime和formCodeId字段。
   • keysExamined: 528，表明在索引扫描中检查了528个键。
   • docsExamined: 20，表示在文档层面上检查了20个文档。
   • cursorExhausted: 1，表示游标已用尽，即已返回了所有符合条件的文档。
   • numYields: 12，指示在查询过程中有12次让出CPU控制权的情况。
   • nreturned: 20，返回了20个文档。
   • reslen: 38504，结果集长度为38504字节。

6. 锁和资源消耗:

   • locks部分详细说明了全局、数据库和集合级别的锁的获取情况，以及获取锁的等待次数和时间。

7. 协议和执行时间:

   • protocol: op_query，指示使用了查询协议。
   • 21658ms，整个查询操作耗时21.658秒。

优化建议：

基于以上分析，以下是一些可能的优化建议：

1. 索引优化:

   • 确保查询条件中的字段都有合适的索引。当前使用了一个复合索引 { creator: 1, deleteStatus: 1, createTime: -1, formCodeId: 1 }，可能需要根据实际查询模式和性能瓶颈进行进一步优化。
   • 考虑是否需要调整索引顺序或者添加新的索引以更好地支持查询。

2. 查询性能分析:

   • 根据实际应用需求和查询频率，分析是否可以通过改进查询逻辑或者数据模型设计来优化查询性能。

3. 锁和资源管理:

   • 如果查询频繁导致了锁争用或者性能瓶颈，可以考虑调整MongoDB实例的配置，如增加硬件资源、优化查询并发度等。

4. 查询响应时间:

   • 监控和分析长时间运行的查询，并考虑是否可以通过分批处理、数据分片或者其他优化手段来降低查询的响应时间。

5. 系统调优:

   • 定期审查和调整MongoDB的配置参数，以最大化系统性能和资源利用率。

综上所述，优化MongoDB查询性能涉及索引设计、查询优化和系统调优等多个方面，需要结合具体业务场景和性能需求进行详细分析和实施。

2024-06-25T15:31:13.677+0800 I COMMAND [conn22721807] command testDB.T_Test command: find { find: "T_Test ", filter: { acceptId: "5e91a373d5deec522a48b6de", deal: 1, todoType: 1, dealTime: { $lt: new Date(1719300655472) } }, sort: { dealTime: -1 }, limit: 11 } planSummary: IXSCAN { acceptId: 1, sourceId: 1, appId: 1 } keysExamined:1548 docsExamined:1548 hasSortStage:1 cursorExhausted:1 numYields:40 nreturned:11 reslen:7369 locks:{ Global: { acquireCount: { r: 82 }, acquireWaitCount: { r: 41 }, timeAcquiringMicros: { r: 11030454 } }, Database: { acquireCount: { r: 41 } }, Collection: { acquireCount: { r: 41 } } } protocol:op_query 18203ms

2024-06-25T15:31:13.677+0800 I COMMAND  [conn22721807] command testDB_T_Test  command: find { find: "T_Test", filter: { acceptId: "5e91a373d5deec522a48b6de", deal: 1, todoType: 1, dealTime: { $lt: new Date(1719300655472) } }, sort: { dealTime: -1 }, limit: 11 } planSummary: IXSCAN { acceptId: 1, sourceId: 1, appId: 1 } keysExamined:1548 docsExamined:1548 hasSortStage:1 cursorExhausted:1 numYields:40 nreturned:11 reslen:7369 locks:{ Global: { acquireCount: { r: 82 }, acquireWaitCount: { r: 41 }, timeAcquiringMicros: { r: 11030454 } }, Database: { acquireCount: { r: 41 } }, Collection: { acquireCount: { r: 41 } } } protocol:op_query 18203ms

这条MongoDB查询日志提供了关于一个查询操作的详细信息。

让我们逐步解读每个部分，并提出可能的优化建议：

1. 时间戳与命令信息：

   • 时间戳：2024-06-25T15:31:13.677+0800
   • 命令类型与连接ID：I COMMAND [conn22721807]
   • 命令内容：command testDB.T_Test command: find ...

2. 查询命令：

   • 数据库：testDB
   • 集合：T_Test
   • 查询内容：find { find: "T_Test", filter: { acceptId: "5e91a373d5deec522a48b6de", deal: 1, type: 1, dealTime: { $lt: new Date(1719300655472) } }, sort: { dealTime: -1 }, limit: 11 }
     • 查询条件：acceptId = "5e91a373d5deec522a48b6de", deal = 1, type = 1, dealTime < 1719300655472
     • 排序方式：按 dealTime 降序排序
     • 限制结果数：11 条记录

3. 执行计划与性能统计：

   • 执行计划摘要：IXSCAN { acceptId: 1, sourceId: 1, appId: 1 }
     • 使用了索引 { acceptId: 1, sourceId: 1, appId: 1 } 进行查询，表示使用了复合索引，首先按 acceptId、sourceId 和 appId 进行索引扫描。
   • 统计信息：
     • keysExamined: 1548
     • docsExamined: 1548
     • hasSortStage: 1
     • cursorExhausted: 1
     • numYields: 40
     • nreturned: 11
     • reslen: 7369
     • 锁信息：Global、Database、Collection 各自的获取次数和等待时间

4. 查询执行时间：

   • 查询耗时：18203ms （约18秒）

优化建议：

基于以上分析，以下是可能的优化建议：

• 索引优化：

  • 确保查询所涉及的字段都有合适的索引。当前查询使用了复合索引 { acceptId: 1, sourceId: 1, appId: 1 }，这对于查询中涉及的字段可能是合适的选择。如果频繁使用 dealTime 进行排序或筛选，考虑是否需要在该字段上添加索引。
  • 可以通过 MongoDB 的 explain() 方法进一步分析索引使用情况，确保索引覆盖了查询的需求，减少 keysExamined 和 docsExamined 的数量。

• 查询条件优化：

  • 考虑查询条件的效率。在本例中，dealTime < 1719300655472 表达式使用了具体的时间戳，确保这个条件是正确的，并且符合业务逻辑。

• 性能监控与调优：

  • 监控数据库性能，尤其是查询的响应时间和索引使用情况。长时间的查询可能暗示了索引优化或者查询逻辑的进一步优化的需要。
  • 考虑是否有其他因素影响了查询性能，如系统负载、硬件性能等。

通过优化索引和查询条件，通常可以显著改善查询性能，减少查询时间并降低系统资源的消耗。

如何过滤出 protocol:op_query 大于 5000ms 的所有日志 ？

awk '/protocol:op_query/ && match($0, /protocol:op_query ([0-9]+)ms/, time) && time[1] > 5000 { print }' mongod.log

• 使用awk命令处理日志文件mongod.log。
• /protocol:op_query/筛选包含"protocol:op_query"的行。
• match($0, /protocol:op_query ([0-9]+)ms/, time) 提取每行中的查询时间（单位为ms），并将其保存在time数组中。
• time[1] > 5000 检查提取出的时间是否大于5000ms。
• { print } 如果满足条件，打印整行日志。

这样，这行命令会输出所有查询时间超过5000ms的日志条目。

awk -F ' ' '{split($NF, a, "ms"); if (a[1] > 5000) print $0}'   mongod.log

这段代码是用 AWK 编写的命令，用于处理文件 mongod.log 中的数据。让我们逐步解读这段命令：

1. 命令结构：

   awk -F ' ' '{split($NF, a, "ms"); if (a[1] > 5000) print $0}' mongod.log
   

2. 解读命令部分：

   • awk -F ' ': 这里使用 -F ' ' 指定了字段分隔符为空格。这意味着每行文本会被按空格分割成多个字段，其中 $NF 表示最后一个字段。

   • '{split($NF, a, "ms"); if (a[1] > 5000) print $0}': 这是 AWK 的脚本部分，用单引号括起来，包含两个命令：

     • split($NF, a, "ms"): 使用 split 函数将最后一个字段 $NF 按照 "ms" 分割成多个部分，结果存储在数组 a 中。这个命令的目的是从末尾字段中提取出以 "ms" 结尾的数值。
     • if (a[1] > 5000) print $0: 如果 a 数组的第一个元素（即从最后一个字段中提取的数值部分）大于 5000，那么打印整行内容 $0。这样可以筛选出满足条件的行。

3. 作用：

   • 此命令的主要作用是读取文件 mongod.txt 的每一行，将最后一个字段按 "ms" 分割成数值部分，并检查这个数值是否大于 5000。如果满足条件，则输出整行内容。

4. 注意事项：

   • 命令中的 $NF 表示最后一个字段，如果每行字段数目不确定或者字段分隔符不仅仅是空格，可能需要根据实际情况调整 -F 参数和 $NF 的使用方式。

这样，整个命令就是一个用 AWK 实现的简单的文本处理流程，用于筛选出满足特定条件的行并进行输出。