目录 一、背景 二、问题定界 三、找出元凶 四、解决思路 声明:本文同步发表于 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 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 也是基于此来实现行级锁的。 几种锁的互斥关系如下表所示: 锁类型 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 到了吗? 作者: 美码师(zale) 出处: http://www.cnblogs.com/littleatp/, 如果喜欢我的文章,请关注我的公众号 本文版权归作者和博客园共有,欢迎转载,但未经作者同意必须保留此段声明,且在文章页面明显位置给出 原文链接 如有问题, 可留言咨询. 分类: 5.数据库中间件https://www.cnblogs.com/littleatp/p/11707952.html