是什么造成了数据库的卡顿

背景

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 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)：

图-listCollection锁

MongoDB 锁机制

为了说明阻塞的产生，这里需要解释下MongoDB的锁机制：

在数据库内部有下面这几种锁：

• 写锁(X)，对某个文档或数据库对象进行写时加锁

• 读锁(S)，对某个文档或数据库对象进行读取时加锁

• 意向写锁(IX)，对文档写操作时，对集合及数据库产生意向写锁

• 意向读锁(IS)，对文档读操作时，对集合及数据库产生意向读锁

意向锁提供了数据库系统的”多粒度锁”的能力，是提升并发能力的关键手段， WiredTiger 也是基于此来实现行级锁的。

几种锁的互斥关系如下表所示：

基于此，我们可以得出这样的结论：

由定时器产生 的 listCollections 操作会对数据库产生读锁(S)，从而对文档写操作(数据库的意向写锁IX)产生了阻塞。

那么，listCollections 从监控的意义上来看是不应该对数据库产生阻塞的。

我们认为这应该是  MongoDB 3.4 版本一个Bug，而SERVER-34243 这里提交的一个Issue已经得到解决。

在最新的 4.x版本文档中，可以发现 listCollections 的权限已经变更成了 意向读锁(IS)。

通过 4.0 版本的 ReleaseNotes 可以确认这点：

链接：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 到了吗？

欢迎关注"美码师"公众号，笔者是十年老兵一枚，欢迎留言打扰，话题不限于技术、职场或生活..  

"写一首代码，做一手好菜"，当技术与美走到一起时，生活也可以是诗和远方