声明：本文同步发表于 MongoDB 中文社区，传送门：
http://www.mongoing.com/archives/26201
一、背景
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 观察到的如下图：
图- 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<String> allCollections = new ArrayList<>();
//get all collections
MongoCursor<String> 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)：
图-listCollection锁
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 到了吗？