MongoDB isMaster命令执行耗时过长问题诱因咨询

异常日志样例 #

2021-09-03T00:15:25.031-0400 I  COMMAND  [conn32] command admin.$cmd command: isMaster { ismaster: 1, $db: "admin", $clusterTime: { clusterTime: Timestamp(1630642509, 884), signature: { hash: BinData(0, E2FBF02AE3EA7D8A6C9863DAAE621E9FCEA528B5), keyId: 6942951450167214081 } } } numYields:0 reslen:845 locks:{} protocol:op_msg 5008ms

常见触发原因 #

• 短连接风暴/连接数过载：isMaster是MongoDB客户端新建连接时默认发送的第一个心跳校验命令，若同一时间有大量短连接发起（比如上游服务批量重启、扩容，客户端连接池配置错误导致频繁销毁重建连接），服务端连接队列被打满，新连接的isMaster命令会排队等待执行，出现毫秒级甚至秒级延迟。17万条异常记录的量级基本可以优先排查该场景。
• 服务端资源耗尽：若异常发生时段MongoDB所在服务器CPU、内存、磁盘IO任意资源被打满，比如同一时间有未索引的慢查询扫表、大批量数据写入/删除、内存不足触发swap交换，即使isMaster是轻量无锁命令，也会因为操作系统调度优先级不足、服务端工作线程被占满而排队延迟。日志中numYields:0也说明命令本身没有因为资源竞争主动让步，耗时基本都来自排队等待。
• 副本集状态异常：如果是副本集架构，节点正在执行全量同步、增量日志追赶、主节点切换等操作时，集群状态元数据更新会被阻塞，isMaster需要返回最新的集群角色、节点列表信息，就会出现延迟。另外如果集群节点间时钟偏差过大，日志中携带的$clusterTime参数校验逻辑也会产生额外开销。
• 近期变更兼容性问题：若异常发生前有过MongoDB服务端版本升级、客户端驱动版本更新、访问权限/审计规则调整，也可能是新的逻辑存在bug，导致isMaster的参数校验、权限校验开销陡增。
• 操作系统网络配置异常：TCP连接队列溢出、TIME_WAIT端口占用过多、防火墙/安全组规则校验新增开销，都会导致新建连接的握手、命令传输阶段耗时变长，体现在日志里就是isMaster执行耗时升高。

快速排查方向 #

• 先拉取异常时间段的连接数监控，对比历史值是否有几倍甚至几十倍的突增
• 核对同时段服务器CPU、内存、磁盘IO、网络IO的监控指标，确认是否存在资源瓶颈
• 检查同一时间的MongoDB慢日志，是否有其他大查询、批量操作占满服务端资源
• 查看副本集状态，确认是否有节点离线、同步滞后、主节点切换事件发生
• 复盘最近24小时内是否有服务端、客户端、网络规则的变更操作

内容的提问来源于stack exchange，提问作者Sumeet Dhingra