记录一次mongodb每一分钟要出现几次慢查询问题

jimmy 2018年11月21日 2,453次浏览
- ## 概述

最近发现生产环境mongodb的一个collection查询慢,导致系统内部dubbo调用超时。mongodb部署的是1个复制集三个节点,一个primary两个secondary。 查询的collection空间占用在300G左右,主键_id是String类型,查询只更具主键查询,查询策略设置的是SecondaryPrefered,优先从从节点查询。 平均查询tps在20左右,一分钟出现几次慢查询,而且慢查询出现在1s内。

为了确定超时的时间我对mongodb的访问加了监控,如下图所示

异常监控

从图中可以看出,读取时间最大要10s,而插入时间只需要最大300ms

问题分析

  1. 网络问题
    因为最近网络出现了各种抖动,特别是系统内部防火墙快达到了最大负荷,所以怀疑是网络问题。
  2. 应用的mongodbclient有bug
    系统使用的morphia做为mongo的client端,由于具体从哪个从读取数据有client决定的,怀疑morphia在高压力下,是否会出现bug。
  3. mongo的服务器问题
    这个是最大的怀疑对象,任何mongo的异常都可能是mongo服务器导致的。
  4. 物理机器问题
    不排除由于机器的问题,硬件问题,系统参数配置问题。

排查过程

由于收到的报警是系统内部错误,查询日志是dubbo调用超时导致的,而且出现的次数很少,且一出现就不只是一笔超时,会有很多笔。

这个dubbo调用超时的情况以前也出现过,主要是网络不稳定,所以开始也怀疑网络是不是又抖动了。 这个dubbo超时有可能是两个地方导致的,调用路径是 业务系统->数据库访问层->mongo实例。 为了判断到底是业务系统->数据库访问层超时,还是数据库访问层->mongo实例之间超时,我在数据库访问层访问mongo的时候加了一个监控,记录访问之前和之后的时间差,并记录到influxdb中,通过grafana能直观的展示出来。就是下面这个图:

监控异常图

这个是放大了的图,可以很明显的看出每一分钟出现一个波动,每个波动有3次,因为我的应用服务器有3个节点,所以每个服务器每一分钟出现了一个波动。波动出现的间隔大约就是1分钟。

由于数据库访问服务器和mongo实例之间没有防火墙,初步排除网络的问题。

为了验证不是morphia的问题,自己写了一个testcast,不停的查询mondo的数据,并观察是否会出现这个问题,由于验证是在测试环境验证的,测试环境的mongo实例是单节点的,所以测试都很正常没有出现这个问题。然后有用mongo原生的java client测试了一下,也没有发现这个问题,准备放到生产环境也测试一下,后面发现了其他原因,排除了morphia,就没有放到生产环境验证。

后面登录到mongo实例机器,打开mongostat观察一下mongo的负载情况,其中一个从节点27发现了异常,另一个从节点26正常。异常的日志如下:

mongostat

把有异常的mongo节点27停掉了,应用读取操作自动切换到了节点26,从监控图上面看,一切正常,没有问题了,定位是mongo节点27有问题。

发现了mongostat在异常那台机器上面每隔一分钟出现了一个flush操作,导致了insert和query的数据量快速减少,过了一会query暴增,到这个时候就怀疑是机器的配置不一样,或者mongo的配置不一样导致的,对网络数据进行抓包分析:

请输入图片描述

这个抓包数据来自又异常的mongo节点27,可以发现了在mongostat异常的时候,网络的流量也有异常,其中有部分的mongo请求4s后才有相应,稳定定位mongo节点27的响应慢导致的。具体为什么响应慢了,还需要具体分析,当天就下班了。

对两台机器的相关配置进行比较,特别是tcp相关的参数,发现参数都是一样的。

对两台mongo从节点进行比较,发现读取的次数比较接近。

查询mongo相关文档,看看有没有什么相关的配置。

可疑点1: 第一个是 fsync配置,这里特别提到了

As applications write data, MongoDB records the data in the storage layer and then writes the data to disk within the syncPeriodSecs interval, which is 60 seconds by default.

60s刷盘一次,和我们出问题的评论吻合,期间尝试手工多刷新几次,把刷盘的数据平均分摊到1分钟以内,看看有没有改善。

db.adminCommand( { fsync: 1, async: true } )

手动刷盘

从监控中发现耗时还是很大,几乎没有什么改善。

可疑点2: ttl 链接

这个collection我设置了ttl来自动清理数据,mongo的清理策略是,如果这个字段的时间超过了设置的时间,就会定时清理掉。清理的方式是在后台启动了一个线程,不停的检查是否有数据是过期数据,过期了就清理掉,这个线程的执行间隔也是60s,所以是不是这个清理导致的呢,但是另一台机器没有这个问题,一时没想明白。

The background task that removes expired documents runs every 60 seconds. As a result, documents may remain in a collection during the period between the expiration of the document and the running of the background task.

在后面就快接近真相了,mongo的同步策略问题,链接 ,我使用的是3台机器,一个复制集,而为了减轻主的压力,mongo并不是所有的从节点都是从主复制oplog,从默认从ping延迟最低的几点同步oplog,所以目前的状态是 主节点->从节点26->从节点27, 将从节点27修改为也从主从同步,这个问题就消失,所以从节点从26同步的oplog可能有问题,数据量太多,导致从节点27的刷盘数据量大,导致从节点27的查询卡住。

总结

通过

cfg = rs.config()
cfg.settings.chainingAllowed = false
rs.reconfig(cfg)

屏蔽了从节点从另一个从节点同步oplog,让两个从节点都从主节点同步oplog,解决了某一个从节点查询周期性延迟的问题。
监控也正常了,下图所示:
请输入图片描述

后记

运行一段时间后,耗时长的情况又出现了,听取了mongo专家的建议,升级到了 3.4.11 ,耗时长的情况没有出现了。

参考了这个,但是现象有点不一样。
https://jira.mongodb.org/browse/SERVER-31101