记一次mongo周期性慢查询问题的定位

enjolras1205 - 2022-02-17 15:48:13

---

问题

线上mongodb主库经常出现以5分钟为周期性的慢查询。在排除业务代码bug，机器cpu/io/memory资源限制后。最终发现是mongodb的bug，因为这是一个非常典型的加锁导致的性能不佳问题。故做一下记录。

过程部分业务出现超时报错

部分业务出现超时报错后，开始定位：

这个超时报错是周期性的，间隔是5分钟。mongodb链接数量呈周期性上升。部分请求的rtt在同一个时间点明显上升。所有高rtt慢查询都出现在主库，并且集中在一秒内。排除了业务出错的可能性

排除业务问题的原因如下：

所有的请求都会出现慢查询，而这些查询在平时应该在0.5MS左右返回，比如主键完全命中，collection规模很小，且返回doc不大。在出现慢查询前后，mongodb业务无变化。因没有秒级监控数据，未在机器层面发现其它异常cpu 的使用率，上下文切换，中断都无异常。disk/network io 无异常。max磁盘使用率在%20以下，等待时间和队列都很低。内存异常变化。增加了专门的告警，抓到秒级的mongotop日志

                                     ns       total        read      write    20XX-XX-XXTXX:XX:06+08:00
            XXXXXXXXXXX    432784ms    427448ms     5336ms                             
              XXXXXXXXXXX.XXXXXXXXXXX    156077ms    156077ms        0ms                             
        XXXXXXXXXXX.XXXXXXXXXXX    123833ms     92224ms    31608ms                             
  XXXXXXXXXXX.XXXXXXXXXXX     94543ms     93360ms     1182ms                             
         XXXXXXXXXXX.XXXXXXXXXXX     87778ms     83832ms     3945ms                             
XXXXXXXXXXX.XXXXXXXXXXX     48675ms     48635ms       40ms                             
            XXXXXXXXXXX.XXXXXXXXXXX     44022ms     44022ms        0ms                             
               XXXXXXXXXXX.XXXXXXXXXXX     29715ms     29715ms        0ms                             
         XXXXXXXXXXX.XXXXXXXXXXX     20737ms      5445ms    15291ms                             
   XXXXXXXXXXX.XXXXXXXXXXX     13962ms     13939ms       22ms      

mongodb bug

在提交工单给阿里云的专家后，正好有人遇到过类似问题，是mongodb的bug。
https://github.com/mongodb/mo...
很遗憾，因为没有在现场再次查看cpu的秒级中断，上下文切换数据，我未能自己找到这个bug。
如果使用vmstat来观测，出问题的那一秒，上下文切换和中断会突然飙到上一秒的1.8倍左右。和mongotop的异常时间点完全吻合。

总结一瞬间的性能问题，需要更高精度的监控数据来定位。可以用off-cpu分析技术来定位此类cpu未跑满但吞吐不佳的问题。
off-cpu注意使用率的陷阱，使用率高不代表一定过载，使用率低也不代表一定空闲。
按分钟计算，磁盘使用率为%20，可以是前10秒使用率为%100。后50秒几乎完全空闲。这个不能说明磁盘未过载。当然这种情况下的await和读写队列并不会特别低。

Tags 标签

mongodbbug

扩展阅读