一次MongoDB查询优化历程

1 问题背景

在项目压力测试过程中，在数据量计达到百万级时，发现查询效率极低，部分查询甚至达到了100S左右，这对一个业务来说，是一件不可接受的事情，因此，进行了一次优化，优化的效率大概是，从100s -> 5s。
虽然看数据来说，5S可能还是一个正常的业务请求难以接受的事情，但是已经满足一开始的需求，对本次的分析做一次简单的总结。

2 分析思路

本次的业务需求是一个分页查询的场景，在查询过程中，需要进行分页跳转、总数计算。
基础的业务代码如下：

            Criteria criteria = getCriteria(queryInfo);
            // 生成query，这里面就是各种查询语句的生成
            Query query = getQuery(queryInfo);
            query.allowDiskUse(true);
            long start = System.currentTimeMillis();
            // 初始化聚合操作、允许使用磁盘内存缓存
            AggregationOptions aggregationOptions = AggregationOptions.builder().allowDiskUse(true).build();
            Aggregation countAggregation =
                    Aggregation.newAggregation(
                            Aggregation.match(criteria), Aggregation.count().as("count"))
                            .withOptions(aggregationOptions);

            List<Map> aMap = mongoTemplate.aggregate(countAggregation, VERIFY_LOG, Map.class).getMappedResults();
            int verifyLogCount = 0;
            if (CollectionUtils.isNotEmpty(aMap)) {
                verifyLogCount = (int) aMap.get(0).get("count");
            }
            long spend = System.currentTimeMillis() - start;
            start = System.currentTimeMillis();
            query.with(Sort.by(
                    Sort.Order.desc("timestamp")
            ));
            if (queryInfo.getPageSize() > CommonConstant.MAX_QUERY_PAGE_SIZE) {
                queryInfo.setPageSize(CommonConstant.MAX_QUERY_PAGE_SIZE);
            }
            if (queryInfo.page() != null) {
                query = query.with(queryInfo.page());
            }
            List<VerifyLogDao> logDaoList = mongoTemplate.find(query, VerifyLogDao.class, VERIFY_LOG);
            spend = System.currentTimeMillis() - start;
            ......
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31

在上面的核心代码中，主要有2个部分：

1. count计算总数
2. 分页查找数据，转为VerifyLogDao 类，在前端进行显示

针对这个两个部分的执行耗时，我们进行打印来查看：

2.1 打印执行耗时，分析耗时点

通过在代码中增加耗时打印，判断哪部分耗时较大：

            Criteria criteria = getCriteria(queryInfo);
            // 生成query，这里面就是各种查询语句的生成
            Query query = getQuery(queryInfo);
            query.allowDiskUse(true);
            long start = System.currentTimeMillis();
            // 初始化聚合操作、允许使用磁盘内存缓存
            AggregationOptions aggregationOptions = AggregationOptions.builder().allowDiskUse(true).build();
            Aggregation countAggregation =
                    Aggregation.newAggregation(
                            Aggregation.match(criteria), Aggregation.count().as("count"))
                            .withOptions(aggregationOptions);

            List<Map> aMap = mongoTemplate.aggregate(countAggregation, VERIFY_LOG, Map.class).getMappedResults();
            int verifyLogCount = 0;
            if (CollectionUtils.isNotEmpty(aMap)) {
                verifyLogCount = (int) aMap.get(0).get("count");
            }
            long spend = System.currentTimeMillis() - start;
            start = System.currentTimeMillis();
            // 打印count耗时
            log.info(
                    "VerifyLogService.queryPagedLogs: count: "
                            + verifyLogCount
                            + " mongoTemplate.count spend "
                            + spend
                            + "ms");
            log.info("VerifyLogService.queryPagedLogs: countQuery: " + query);
            query.with(Sort.by(
                    Sort.Order.desc("timestamp")
            ));
            if (queryInfo.getPageSize() > CommonConstant.MAX_QUERY_PAGE_SIZE) {
                queryInfo.setPageSize(CommonConstant.MAX_QUERY_PAGE_SIZE);
            }
            if (queryInfo.page() != null) {
                query = query.with(queryInfo.page());
            }
            List<VerifyLogDao> logDaoList = mongoTemplate.find(query, VerifyLogDao.class, VERIFY_LOG);
            spend = System.currentTimeMillis() - start;
            // 打印最终耗时
            log.info(" mongoTemplate.query spend " + spend + "ms");
            ......
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41

经过打印之后发现：
1. count计算总数耗时约60s
2. 最终耗时约120S
其中，对于count函数的耗时，由于mongDB的特性，耗时长早有预料，但是对于mongoTemplate.find()方法的耗时明显是不合理的。

因此，在经过网上的相关搜索后，发现：
在数据量大时，直接使用find函数查找数据，会在内存中将所有的数据在内存中存放，并且转换为相关的dao类，对内存消耗会很大，耗时会十分严重。 为了避免该问题，决定使用cusor的形式来进行分批查询，同时使用手动将数据进行convert的方法，避免自动转换的耗时问题。

核心代码如下：

// 使用cursor进行查询
            MongoCursor<Document> cursor = mongoTemplate.getCollection(VERIFY_LOG).find(query.getQueryObject())
                    .noCursorTimeout(true).batchSize(2000).limit(queryInfo.getPageSize()).skip(queryInfo.getPageSize()
                            * (queryInfo.getPageNo() - 1)).cursor();
            // 手动将数据转换为dao类                
            List<VerifyLogDao> logDaoList = new ArrayList<>();
            while (cursor.hasNext()) {
                Document document = cursor.next();
                VerifyLogDao verifyLogDao = new VerifyLogDao();
                convertDocumentToVerifyDao(document, verifyLogDao);
                logDaoList.add(verifyLogDao);
            }
1
2
3
4
5
6
7
8
9
10
11
12

经过这一步，发现find()已经优化到毫秒级别，接下来就是开始优化count函数相关部分。
对于count函数的部分优化，由于在代码层面看起来已经没有明显问题：使用了聚合进行查询，直接用count函数进行查询。
但是耗时还是不及预期，因此只能通过最原始的方式：查询慢查询日志。

2.3 慢查询日志分析

• 慢查询日志指的是会将耗时超过一定时间的查询请求执行计划的相关所有日志记录下来，以供分析。

• 通过 MongoDB shell 启用

    #  为所有数据库开启慢查询记录
  
    db.setProfilingLevel(2)
  1
  2
  3

• 慢查询日志核心字段：

{
    "timestamp": "Thu Apr  2 07:51:50.985"  // 日期和时间, ISO8601格式
    "severityLevel": "I"  // 日志级别 I代表info的意思，其他的还有F,E,W,D等
    "components": "COMMAND"  //组件类别，不同组件打印出的日志带不同的标签，便于日志分类
    "namespace": "animal.MongoUser_58"  //查询的命名空间，即
    "operation": "find" //操作类别，可能是[find,insert,update,remove,getmore,command]
    "command": { find: "MongoUser_58", filter: { $and: [ { lld: { $gte: 18351 } }, { fc: { $lt: 120 } }, { _id: { $nin: [1244093274 ] } }, { $or: [ { rc: { $exists: false } }, { rc: { $lte: 1835400100 } } ] }, { lv: { $gte: 69 } }, { lv: { $lte: 99 } }, { cc: { $in: [ 440512, 440513, 440514, 440500, 440515, 440511, 440523, 440507 ] } } ] }, limit: 30 } //具体的操作命令细节
    "planSummary": "IXSCAN { lv: -1 }", // 命令执行计划的简要说明，当前使用了 lv 这个字段的索引。如果是全表扫描，则是COLLSCAN
    "keysExamined": 20856, // 该项表明为了找出最终结果MongoDB搜索了索引中的多少个key
    "docsExamined": 20856, // 该项表明为了找出最终结果MongoDB搜索了多少个文档
    "cursorExhausted": 1, // 该项表明本次查询中游标耗尽的次数
    "keyUpdates":0,  // 该项表名有多少个index key在该操作中被更改，更改索引键也会有少量的性能消耗，因为数据库不单单要删除旧Key，还要插入新的Key到B-Tree索引中
    "writeConflicts":0, // 写冲突发生的数量，例如update一个正在被别的update操作的文档
    "numYields":6801, // 为了让别的操作完成而屈服的次数，一般发生在需要访问的数据尚未被完全读取到内存中，MongoDB会优先完成在内存中的操作
    "nreturned":0, // 该操作最终返回文档的数量
    "reslen":110, // 结果返回的大小，单位为bytes，该值如果过大，则需考虑limit()等方式减少输出结果
    "locks": { // 在操作中产生的锁，锁的种类有多种，如下
        Global: { acquireCount: { r: 13604 } },   //具体每一种锁请求锁的次数
        Database: { acquireCount: { r: 6802 } }, 
        Collection: { acquireCount: { r: 6802 } } 
    },
    "protocol": "op_command", //  消息的协议
    "millis" : 69132, // 从 MongoDB 操作开始到结束耗费的时间，单位为ms
}
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24

这里我们一般主要关注的是nscanned(扫描的记录数) 、nreturned(返回结果的记录数) 。如果nscanned >> nreturned 说明多了很多无效查询，就可以增加索引进行优化。
在这步分析之后，开始用索引进行优化，但是发现优化后，nscanned跟 nreturned的比值还是没有明显变化，说明索引没有生效，通过查询代码发现，是使用了or() 方法，导致查询索引没有生效 ，将or() 的逻辑去掉之后，索引生效，查询条数的问题解决。
解决完该问题之后，发现还存在一个问题，直接用mongoTemplate.count()，执行的sql语句会变成先filter再count，导致耗时加长。该问题是spring提供的mongoDB的通病，因此这里使用手动拼接mongoDB函数解决：

            Document countDocument = mongoTemplate.executeCommand(Document.parse("{\n" +
                    "\t\t\"count\" : \"verify_log\",\n" +
                    "\t\t\"query\" : {\n" +
                    "\t\t\t\"tenantId\" : " + "\"" + queryInfo.getTenantId() + "\"" + ",\n" +
                    "\t\t\t\"timestamp\" : {\n" +
                    "\t\t\t\t\"$gte\" :" + startTime + ",\n" +
                    "\t\t\t\t\"$lte\" : " + endTime + "\n" +
                    "\t\t\t}\n" +
                    "\t\t}" +
                    "\t}"));
1
2
3
4
5
6
7
8
9
10

至此，所有的优化结束，count函数时间页顺利降到了秒级。

3 总结

• 对于数据量大的查询，不建议直接用find方法，做对象的类型转换
• 对于数据量大，需要用索引进行优化的查询条件，不要使用$ ne、$ not、$ or等方法，会导致索引失效
• 正确使用慢查询日志，可以很好的帮助分析具体的耗时问题

参考资料

https://www.jianshu.com/p/27775ae48f29
https://www.ycpai.cn/python/3xffrkNZ.html