声明:本文同步发表于 MongoDB 中文社区,传送门:
http://www.mongoing.com/archives/26201

一、背景

MongoDB 提供了非常强大的性能分析及监控的命令,诸如 mongostat、mongotop 可以让我们对数据库的运行态性能了如指掌。
然而,这次我们在性能环境上就遇到一个非常棘手的问题:

某服务接口在 1-5分钟内偶现超时导致业务失败!

在接口调用上返回超时属于前端的判断,通常是设置的一个阈值(比如 3s)。
由于问题是偶现,且没办法发现有明显的规律,很难直接判断出原因。
而平台在做了微服务拆分之后,问题定位的难度加大了不少,且当前的调用链功能也不够完善。

二、问题定界

业务诊断

在一番分析后,梳理出接口调用的关系图如下:
是什么造成了数据库的卡顿-LMLPHP

其中,服务A 通过 RPC调用服务B的接口,而服务B 又通过 MongoDB 进行数据读写。
MongoManager 是 用于管理 MongoDB 的一个代理服务,主要是实现一些数据备份、监控的任务。

在采集了一些数据之后,我们基本把问题范围锁定到了 MongoDB 数据库上面,这些手段包括:

  • 通过对服务A、服务B的接口监控进行观测
  • 通过wiredshark 抓包,分析 DB读写上的响应包时延
  • 通过CommandListener,将1s 以上的慢操作指标进行输出

从接口监控及 wiredshark 抓包结果中确认到,DB 操作的响应时间都出现了偶现的超长(3s以上)。
而通过 CommandListener 将慢操作输出统计后,得到的图表如下:

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

其中典型的慢操作语句如:

update app.BussinessData
    query: { snId: "c1190522-6b6f-9192-b40a-6665ba2b2tta" }
    update: {
 $set: {
     taskInfo.state: "Running",
     lastModifiedTime: new Date(1531857361579)
 } } 

然而,这些慢操作并没有明显的问题嫌疑,除了以写操作为主之外,索引的命中也没有问题。

数据库诊断

接下来,我们将焦点集中到了数据库上,检查了 cpu、内存、网络、磁盘这些常规指标后并没有发现什么异常。
通过 mongostat 观察到的如下图:

是什么造成了数据库的卡顿-LMLPHP
图- mongostat

其中的一个异常点是 netout 会有偶现的积压情况
然后是尝试通过 db.currentOp() 这个命令来看看能不能揪出慢操作背后的元凶。

然而,我的想法落空了,这个办法并没有任何发现! 因为问题属于偶现,所以执行currentOp 需要一些好的运气..
尽管如此,我们还是大概能判定,在出现慢操作的时候,数据库出现了命令积压(卡顿)的情况

基于上面的这些诊断信息,我们还是没办法直接得出结论,但是大家都做出来一致的猜测:

"可能存在某个定时器的锁,对业务操作产生了阻塞!"

那么,锁从哪里来? 我们将目光移向了 MongoManager,的确这个程序承载了许多管理上的功能,包括监控、备份、升级这些琐事..
其中,执行数据库信息采集的监控定时器存在最大的嫌疑!,那么问题又来了,

"如果是定时器导致的卡顿,为什么慢操作却没有定时产生的规律呢?"

这个问题在前面也对我们产生了很大的困扰,但一个比较合理的解释是:

"MongoManager 是多节点的,而其中定时器是按照 时间间隔来运作的,而不是整点触发。"
这样就能解释,为什么慢操作通常都是在1-5分钟内不规律的出现了。
为了证实这个想法,我们直接将 MongoManager 逐个关闭到仅剩下一个,最终通过CommandListener收集到的慢操作图表如下:

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

看,这次的慢操作非常的规律,基本每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):

是什么造成了数据库的卡顿-LMLPHP
图-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 可以确认这点:

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 到了吗?

10-20 22:32