MongoDB 临时表横空出现1万+,这条语句执行前请准备好翻车的姿势

解决问题之前,先在脑海中演绎一下当时场景

某日早上八点半,笔者接到客户反馈,门户首页待办访问异常缓慢,经常出现“访问异常,点击重试”。当时直觉告诉我,应该是大量用户高并发访问 MongoDB 库,导致 MongoDB 库连接池出问题了,因为上线发版时,功能是正常的。

由于是上周五晚上发版验证后,周六日使用门户的用户比较少,一直没发现问题,直到下周一才集中爆发门户访问不可用。

请开始我的表演

一开始运维组认为是加了 MongoDB 审计日志造成的,因为有大量针对 MongoDB 做写审计日志写操作,确实会降低服务器性能。 通过查看服务日志,也发现非常多的 MongoDB 访问 timeout 异常信息。

<code>com.mongodb.MongoTimeoutException: Timed out after 30000 ms while waiting for a server that matches ReadPreferenceServerSelector{readPreference=primary}. Client view of cluster state is {type=UNKNOWN, servers=[{address=10.236.2.183:27017, type=UNKNOWN, state=CONNECTING, exception={com.mongodb.MongoSocketOpenException: Exception opening socket}, caused by {java.net.ConnectException: Connection refused (Connection refused)}}, {address=10.236.2.184:27017, type=UNKNOWN, state=CONNECTING, exception={com.mongodb.MongoSocketOpenException: Exception opening socket}, caused by {java.net.ConnectException: Connection refused (Connection refused)}}, {address=10.236.2.185:27017, type=UNKNOWN, state=CONNECTING, exception={com.mongodb.MongoSocketOpenException: Exception opening socket}, caused by {java.net.ConnectException: Connection refused (Connection refused)}}] at com.mongodb.connection.BaseCluster.createTimeoutException(BaseCluster.java:377) ~[mongodb-driver-core-3.4.2.jar!/:na] at com.mongodb.connection.BaseCluster.selectServer(BaseCluster.java:104) ~[mongodb-driver-core-3.4.2.jar!/:na] at com.mongodb.binding.ClusterBinding$ClusterBindingConnectionSource.<init>(ClusterBinding.java:75) ~[mongodb-driver-core-3.4.2.jar!/:na] at com.mongodb.binding.ClusterBinding$ClusterBindingConnectionSource.<init>(ClusterBinding.java:71) ~[mongodb-driver-core-3.4.2.jar!/:na] at com.mongodb.binding.ClusterBinding.getReadConnectionSource(ClusterBinding.java:63) ~[mongodb-driver-core-3.4.2.jar!/:na] at com.mongodb.operation.OperationHelper.withConnection(OperationHelper.java:402) ~[mongodb-driver-core-3.4.2.jar!/:na] at com.mongodb.operation.MapReduceWithInlineResultsOperation.execute(MapReduceWithInlineResultsOperation.java:381) ~[mongodb-driver-core-3.4.2.jar!/:na] at com.mongodb.operation.MapReduceWithInlineResultsOperation.execute(MapReduceWithInlineResultsOperation.java:70) ~[mongodb-driver-core-3.4.2.jar!/:na] at com.mongodb.Mongo.execute(Mongo.java:836) ~[mongodb-driver-3.4.2.jar!/:na] at com.mongodb.Mongo$2.execute(Mongo.java:823) ~[mongodb-driver-3.4.2.jar!/:na] at com.mongodb.DBCollection.mapReduce(DBCollection.java:1278) ~[mongodb-driver-3.4.2.jar!/:na] at org.springframework.data.mongodb.core.MongoTemplate.mapReduce(MongoTemplate.java:1406) ~[spring-data-mongodb-1.10.1.RELEASE.jar!/:na] at org.springframework.data.mongodb.core.MongoTemplate.mapReduce(MongoTemplate.java:1383) ~[spring-data-mongodb-1.10.1.RELEASE.jar!/:na] at com.unicom.portal.taskquery.common.TaskManager.selectPendingCountByType(TaskManager.java:1002) ~[classes!/:1.0.0] at com.unicom.portal.taskquery.service.impl.TaskServiceImpl.getPendingInfo(TaskServiceImpl.java:233) ~[classes!/:1.0.0] at com.unicom.portal.taskquery.controller.TaskPendController.getPendingInfo(TaskPendController.java:164) ~[classes!/:1.0.0]/<code>

同时运维人员通过监控告警发现 MongoDB 数据库的连接数达到 10499(平时监控为几百),而 MongoDB 数据库凭空多出惊人的一万多张临时表记录。

查看 K8s 容器平台服务器资源情况,发现待办服务 CPU 资源使用高达 7G 多,内存使用高达 12G。平常待办服务的CPU 资源使用都是 0.00 几,明显感觉不正常。

这似乎更加验证了是加了审计日志造成的,于是运维组开始了非常耗时的 Mongos 停止并重启操作,但很遗憾的是“ Mongos 重启后不久又自动停止了”( 后来跟运维组沟通,加的审计日志跟 MongoDB 半毛钱关系都没有)。 由于这个误导,导致门户大概四十分钟不可用。笔者没办法,只能仔细分析 docker 容器日志,发现大部分错误由同一个方法造成的。

<code>com.unicom.portal.taskquery.common.TaskManager.selectPendingCountByType(TaskManager.java:1002)/<code>

通过代码走读发现 TaskManager.selectPendingCountByType 这个方法用到了 MongoDB 的 mapReduce 方法。

<code>org.springframework.data.mongodb.core.MongoTemplate.mapReduce/<code>

通过查阅 MongoDB 官方文档知悉, mapReduce 方法类似于 MySQL 中的 group by 语句,非常适合做表字段聚合(分组)分类统计功能。 了解 Hadoop 的同学知道,Hadoop 中的 Map 和 Reduce 会拆成多个子任务进行后台跑批计算的。而 MongoDB 的 mapReduce 方法同样如此,不同的是 mapReduce 方法会把子任务发送到不同的分片(sharding)服务器上去执行,而这个过程是非常耗时的。 平常几十个人使用这个功能不会觉察到访问有问题,但是门户每天近 12W 的用户同时在八点半之后访问这个功能,后果就不堪设想了。 结果是“

修改后的待办待阅查询服务在读取/存储过程中会创建大量临时表,高并发时会造成待办 MongoDB 数据库频繁执行和删表操作,致使服务器资源异常占满,MongoDB 数据库进程异常关闭。

笔者初步定位是这个 TaskManager.selectPendingCountByType 统计方法出问题后,果断要求运维组把后台服务恢复到上一个版本后,门户访问正常,待办数据能够正常显示,问题解决!

查看待办服务容器资源使用情况,CPU 使用率明显下降近 7 倍。

心中预案,处理泰然

08:20 运维人员通过监控告警发现 MongoDB 数据库的连接数达到 10499(平时监控为几百),开始检查处理。

08:31 运维人员检查发现 Mongos 进程停止,尝试重新启动,发现重启后不久又自动停止了。

08:37 运维人员分析可能因5月9日晚后台开启了门户 MongoDB 审计日志导致数据库开销较大,故开始回退 6 台 mongoDB 上的审计日志功能。

08:50 回退审计日志操作完成,再次启动 Mongos 进程发现不久又自动停止。

09:06 尝试先停止待办查询应用服务,阻断应用 Mongos的调用,再启动 Mongos 进程。

09:20 西咸机房维护人员配合检查 MongoDB 的服务器资源使用情况后反馈无问题。同时数据库运维人员复查关闭 MongoDB 审计日志回退操作是确认已经回退成功。

09:31 项目组分析5月9日晚上发版的“待办待阅数量查询接口优化”功能可以与此故障有关,因此开始尝试回退待办查询应用代码。

09:36 待办查询应用代码服务回退成功,同时测试发现门户待办业务恢复正常。

09:40 观测前台业务和后台服务稳定后,上报故障恢复。

16:00 联系 17 个全国应用系统完成 9 位一级 VIP 和信息化 3 位领导的待办待阅差异比对,共处理 3 条待办差异。

知其然也要知其所以然

Mongodb 官网对 MapReduce 函数介绍:

Map/reduce in MongoDB is useful for batch processing of data and aggregation operations. It is similar in spirit to using something like Hadoop with all input coming from a collection and output going to a collection. Often, in a situation where you would have used GROUP BY in SQL, map/reduce is the right tool in MongoDB.

大致意思:

Mongodb中的Map/reduce主要是用来对数据进行批量处理和聚合操作,有点类似于使用Hadoop对集合数据进行处理,所有输入数据都是从集合中获取,而MapReduce后输出的数据也都会写入到集合中。通常类似于我们在SQL中使用 Group By语句一样。

MongoDB 有两种数据计算 聚合操作,一种是 Pipeline,另一种是 MapReduce。 Pipeline 的优势在于查询速度比 MapReduce 要快,但是 MapReduce 的强大之处在于它能够在多台分片(Sharding)节点上并行执行复杂的聚合查询逻辑。

那 MapReduce 有哪些优缺点呢?

MapReduce 优点在于能够充分利用 CPU 多核资源(多线程),并发执行 Sharding 分片任务,做分组统计。另外对于一些聚合函数,如 SUM、AVG、MIN、MAX,需要通过 mapper 和 reducer 函数来定制化实现。MapReduce 缺点在于非常耗 CPU 资源并且非常吃内存,其逻辑是首先执行分片查询任务计算线程,计算结果先放内存(吃内存),然后把计算结果存放到 MongoDB 临时表,最后由 finalize 方法统计结果并删除临时表记录。

MapReduce 执行流程

MapReduce 工作分为两步,一是映射,即 map,将数据按照某一个规则映射到一个数组里,比如按照 type 或者 name映射,同一个 type 或者 name 的数据形成一个数组,二是规约,即 reduce,它接收映射规则和数组,然后计算。举例如下:

使用 MapReduce 要实现两个函数:Map 和 Reduce。 Map 函数调用 emit(key,value) 遍历集合中所有的记录,将 key与 value 传给 Reduce 函数进行处理。Map 函数和 Reduce 函数是使用 JavaSript 编写的,其内部也是基于 JavaSript V8 引擎解析并执行,并可以通过 db.runCommand 或 mapreduce 命令来执行 MapReduce 操作。

并发性

我们都知道,Mongodb 中所有的读写操作都会加锁(意向锁),MapReduce 也不例外。MapReduce 涉及到 mapper、reducer,中间过程还会将数据写入临时的 collection 中,最终将 finalize 数据写入 output collection。

read 阶段将会使用读锁(读取 chunks 中的数据),每处理 100 条 documents 后重新获取锁(yields)。写入临时 collectin 使用写锁,这个不会涉及到锁的竞争,因为临时 collection 只对自己可见。

在创建 output collection 时会对 DB 加写锁,如果 output collection 已经存在,且 action 为 replace 时,则会获取一个 global 级别的写锁,此时将会阻塞 mongod 上的所有操作(影响很大),主要是为了让数据结果为 atomic ;如果 action 为 merge 或者 reduce,且 nonAtomic为 true 是,只会在每次写入数据时才会获取写锁,这对性能几乎没有影响。

来个复盘吧

总的来说,还是对 Mongodb 的 MapReduce 方法了解不够深入;同时代码评审时没有重视代码评审的质量,服务器监控方面也待加强。另外对于高并发的地方没有做必要的接口压力测试。 所以,接下来需要加强项目组危机意识,不管是管理流程,代码质量,还是服务器资源监控以及必要的性能测试等。上线发版前,做好事前控制,事中做好服务监控,事后做好复盘,避免下次犯同样的错误。

参考

https://www.csdn.net/article/2013-01-07/2813477-confused-about-mapreduce https://blog.csdn.net/iteye_19607/article/details/82644559