一、背景
MongoDB 提供了非常强大的性能分析及监控的命令,诸如 mongostat、mongotop 可以让我们对数据库的运行态性能了如指掌。
然而,这次我们在性能环境上就遇到一个非常棘手的问题:
某服务接口在 1-5分钟内偶现超时导致业务失败!
在接口调用上返回超时属于前端的判断,通常是设置的一个阈值(比如 3s)。
由于问题是偶现,且没办法发现有明显的规律,很难直接判断出原因。
而平台在做了微服务拆分之后,问题定位的难度加大了不少,且当前的调用链功能也不够完善。
二、问题定界
业务诊断
在一番分析后,梳理出接口调用的关系图如下:
其中,服务A 通过 RPC调用服务B的接口,而服务B 又通过 MongoDB 进行数据读写。
MongoManager 是 用于管理 MongoDB 的一个代理服务,主要是实现一些数据备份、监控的任务。
在采集了一些数据之后,我们基本把问题范围锁定到了 MongoDB 数据库上面,这些手段包括:
- 通过对服务A、服务B的接口监控进行观测
- 通过wiredshark 抓包,分析 DB读写上的响应包时延
- 通过CommandListener,将1s 以上的慢操作指标进行输出
从接口监控及 wiredshark 抓包结果中确认到,DB 操作的响应时间都出现了偶现的超长(3s以上)。
而通过 CommandListener 将慢操作输出统计后,得到的图表如下:
其中典型的慢操作语句如:
update app.BussinessData
query: { snId: "c1190522-6b6f-9192-b40a-6665ba2b2tta" }
update: {
$set: {
taskInfo.state: "Running",
lastModifiedTime: new Date(1531857361579)
} }
然而,这些慢操作并没有明显的问题嫌疑,除了以写操作为主之外,索引的命中也没有问题。
数据库诊断
接下来,我们将焦点集中到了数据库上,检查了 cpu、内存、网络、磁盘这些常规指标后并没有发现什么异常。
通过 mongostat 观察到的如下图:
其中的一个异常点是 netout 会有偶现的积压情况。
然后是尝试通过 db.currentOp() 这个命令来看看能不能揪出慢操作背后的元凶。
> currentOp 还是比较好用的,尤其是在定位一些长时间慢操作问题上
然而,我的想法落空了,这个办法并没有任何发现! 因为问题属于偶现,所以执行currentOp 需要一些好的运气..
尽管如此,我们还是大概能判定,在出现慢操作的时候,数据库出现了命令积压(卡顿)的情况
基于上面的这些诊断信息,我们还是没办法直接得出结论,但是大家都做出来一致的猜测:
“可能存在某个定时器的锁,对业务操作产生了阻塞!”
那么,锁从哪里来? 我们将目光移向了 MongoManager,的确这个程序承载了许多管理上的功能,包括监控、备份、升级这些琐事..
其中,执行数据库信息采集的监控定时器存在最大的嫌疑!,那么问题又来了,
“如果是定时器导致的卡顿,为什么慢操作却没有定时产生的规律呢?”
这个问题在前面也对我们产生了很大的困扰,但一个比较合理的解释是:
“MongoManager 是多节点的,而其中定时器是按照 时间间隔来运作的,而不是整点触发。”
这样就能解释,为什么慢操作通常都是在1-5分钟内不规律的出现了。
为了证实这个想法,我们直接将 MongoManager 逐个关闭到仅剩下一个,最终通过CommandListener收集到的慢操作图表如下:
看,这次的慢操作非常的规律,基本每5分钟就会出现一次卡顿!
然后我们将全部的 MongoManager 关闭,业务的慢操作完全消失了。
三、找出元凶
经过前面的问题定位,我们已经能确定是MongoManager的定时器搞的鬼了。
接下来走读代码,发现有下面这样的一段实现:
public void testDbOperation() {
try {
MongoClient client = getClient();
MongoDatabase database = client.getDatabase("thisdb");
List allCollections = new ArrayList();
//get all collections
MongoCursor iCollection = database.listCollectionNames().iterator();
while (iCollection.hasNext()) {
allCollections.add(iCollection.next());
}
if (allCollections.isEmpty()) {
return;
}
//test a random collection
String randomCollection = allCollections.get((int) (allCollections.size() * Math.random()));
//issue find operation
database.getCollection(randomCollection).find().first();
} catch (Exception e) {
throw new DBMonitException("the db find test failed..", e);
}
}
为了便于理解,上述的代码做了比较多的简化,大致的步骤是:
- 通过 listCollections 获取数据库的全部集合;
- 随机选取一个集合,执行findOne操作;
- 一旦发现操作失败,产生异常(告警)
上述的代码由定时器在5分钟触发一次,跟出现慢操作的条件是吻合的。
其中 listCollections 会获取到一个集合的列表,我们猜测,这个操作可能会阻塞数据库的操作。
通过搜索官方文档,我们发现该操作使用了一个共享读锁(S):
MongoDB 锁机制
为了说明阻塞的产生,这里需要解释下MongoDB的锁机制:
在数据库内部有下面这几种锁:
- 写锁(X),对某个文档或数据库对象进行写时加锁
- 读锁(S),对某个文档或数据库对象进行读取时加锁
- 意向写锁(IX),对文档写操作时,对集合及数据库产生意向写锁
- 意向读锁(IS),对文档读操作时,对集合及数据库产生意向读锁
意向锁提供了数据库系统的”多粒度锁”的能力,是提升并发能力的关键手段, WiredTiger 也是基于此来实现行级锁的。
几种锁的互斥关系如下表所示:
锁类型 | S | X | IS | IX |
---|---|---|---|---|
S | T | F | T | F |
X | F | F | F | F |
IS | T | F | T | T |
IX | F | F | T | T |
基于此,我们可以得出这样的结论:
由定时器产生 的 listCollections 操作会对数据库产生读锁(S),从而对文档写操作(数据库的意向写锁IX)产生了阻塞。
那么,listCollections 从监控的意义上来看是不应该对数据库产生阻塞的。
我们认为这应该是 MongoDB 3.4 版本一个Bug,而SERVER-34243 这里提交的一个Issue已经得到解决。
在最新的 4.x版本文档中,可以发现 listCollections 的权限已经变更成了 意向读锁(IS)。
通过 4.0 版本的 ReleaseNotes 可以确认这点:
The command listCollections takes Intent Shared lock on the database.
In previous versions, the command takes Shared lock on the database.
链接: https://docs.mongodb.com/manual/release-notes/4.0/index.html
四、解决思路
在了解了事情的来龙去脉之后,我们可以确定这是 MongoDB 3.4 版本的一个不严谨的实现导致的问题。
由于无法直接升级整个数据库版本(代价太大), 我们在监控程序上做了优化,即将 listCollections 结果进行了缓存,避免定时器每次都去操作这个命令,而问题最终得到了解决。
“监控不是银弹,滥用也会有坑”,至少从这次的事件中,我们得到了一个教训!
而要在这个问题上举一反三的话,那就是需要警惕一些数据库操作潜在的锁问题了,比如:
- 创建索引(默认Foreground模式),会对数据库产生写锁(X),所以一定要用Background模式
- 删除集合,dropCollection,会对数据库产生写锁(X),谨慎!
- MapReduce操作,会对数据库产生读锁(S)和写锁(X),谨慎!
- 连接鉴权,db.auth(),会对admin库产生读锁,而admin是库级锁。
以上的这些事情,你 get 到了吗?
是怎么猜出”可能存在某个定时器的锁,对业务操作产生了阻塞”的?这个很神奇,哈哈
.此前的调优曾有过类似问题
博主,你想,如果有一个监控面板,记录了系统上锁情况,那么此种问题一出,看看面板,就会发现锁value 定时变化 ,那么就很快捷了。问题是,面板要搞出来