mongodb python 大于_记一次 MongoDB 慢日志优化历程

最新推荐文章于 2021-02-19 13:48:30 发布

自闭成年人

最新推荐文章于 2021-02-19 13:48:30 发布

阅读量333

点赞数

文章标签： mongodb python 大于

本文链接：https://blog.csdn.net/weixin_32148861/article/details/112184768

版权

可直接点击上方蓝字

(网易游戏运维平台)

关注我们，获一手游戏运维方案

运维开发工程师，负责游戏系统配置管理平台的设计和开发，目前专注于新 CMDB 系统的开发，平时也关注运维自动化，DevOps，Python 开发等技术。

背景

CMDB 为了使用事务来存储机器的数据，启用了 mongodb4.0 版本，在平均 1.5k qps 并发写的情况下(这只是机器层面的数据，机器的里面有很多子资源的更新，每个子资源的更新会对应一个 mongodb 操作)，mongodb 一直处于高负载状态，导致很多操作变得很慢，从慢日志的统计来看，严重的时候，一小时可以产生 14w+ 条慢日志，使得数据消费的速度下降，导致队列出现堆积，优化迫在眉睫。优化的方向主要有两个，一个在业务层面控制数据的写入速度，一个是在数据库端尝试进行优化，提高数据库的写入性能。本篇文章主要聚焦在数据库层面的优化。

mongodb 索引简介

为了方便理解后面的优化思路，先简单介绍 mongodb 的索引，但不会太详细，只会涉及到本次优化中使用到的索引类型。

mongodb 的索引类型分为：

单键索引(Single Field Index)
复合索引(Compound Index)
多键索引(Multikey Index)
地理空间索引(Geospatial Index)
文本索引(Text Indexes)
哈希索引(Hashed Indexes)

如果我们想要定义某个索引为唯一索引，可以使用索引的属性来定义，索引的属性有：

唯一索引
部分索引
稀疏索引
TTL 索引

galaxyx 存储机器资源的集合，主要使用了单键索引(唯一索引)，复合索引，多键索引，以下的内容只会涉及到这三种索引，其他索引的介绍请参考官方文档。

索引的存储

mongodb 索引使用 B-Tree 数据结构来存储，B-Tree 的每个节点都存放创建索引的 key 的值 (value)，以及该值对应文档的存储位置信息(mmapv1 和 wiredTiger 生成位置信息的方式不同)，存储引擎再通过该位置信息从磁盘中读取对应的文档数据。这种存储方式和 mysql 的非聚集索引类似，不同的是 mysql 索引使用 B+Tree ，只有叶子节点才存放数据，如果使用 innodb 引擎，叶子节点上存放的对应行的 primary key 的值，查找任何一行数据的磁盘 IO 次数与索引的树高度相同，而 mongodb 索引全部节点都可以存储数据，最好的情况下只用进行一次磁盘 IO，最坏的情况也是和索引树高度相同。

下面通过一个例子来解释 mongodb 的索引结构，比如有一个集合(users)，文档存放着用户的名字(name)，年龄(age)，孩子(childrens), 测试数据如下：

1{"name": "a", "age": 30, "childrens": [{"name": "a_a", "age": 3}, {"name": "a_b", "age": 1}]}
2{"name": "b", "age": 30, "childrens": [{"name": "b_a", "age": 2}]}
3{"name": "c", "age": 32, "childrens": [{"name": "c_a", "age": 4}, {"name": "c_b", "age": 1}]}
4{"name": "e", "age": 33, "childrens": [{"name": "e_a", "age": 5}, {"name": "e_b", "age": 2}]}
5{"name": "f", "age": 32, "childrens": [{"name": "f_a", "age": 4}, {"name": "f_b", "age": 1}]}
6{"name": "d", "age": 40, "childrens": [{"name": "d_a", "age": 10}]}
7{"name": "g", "age": 42, "childrens": [{"name": "g_a", "age": 12}, {"name": "g_b", "age": 8}]}

经过存储引擎持久化之后，集合的每个文档都拥有一个存放的位置信息，可以理解为超市寄存柜的编号。

如果对 age 创建一个单键索引：

1db.users.createIndex({'agen': 1})

那么索引的数据如下所示：

1age   位置               磁盘上的文档
230    position3   ->    {"name": "a", "age": 30, "childrens": [{"name": "a_a", "age": 3}, {"name": "a_b", "age": 1}]}
330    position5   ->    {"name": "b", "age": 30, "childrens": [{"name": "b_a", "age": 2}]}
432    position1   ->    {"name": "c", "age": 32, "childrens": [{"name": "c_a", "age": 4}, {"name": "c_b", "age": 1}]}
532    position2   ->    {"name": "f", "age": 32, "childrens": [{"name": "f_a", "age": 4}, {"name": "f_b", "age": 1}]}
633    position4   ->    {"name": "e", "age": 33, "childrens": [{"name": "e_a", "age": 5}, {"name": "e_b", "age": 2}]}
740    position6   ->    {"name": "d", "age": 40, "childrens": [{"name": "d_a", "age": 10}]}

age 是索引节点上的 key，位置是索引节点的 value，代表磁盘中文档存放的位置。

如果对 name 和 age 创建一个复合索引：

1db.users.createIndex({'name': 1, 'agen': 1})

那么索引的数据如下：

1name,age   位置      
2a,30    position3 
3b,30    position5 
4c,32    position1
5f,32    position2
6e,33    position6
7d,40    position4

如果对 age 和 childrens 的 name 字段创建一个复合索引，因为 childrens 是一个数组，存储引擎会自动转化为多键索引，索引的数据如下：

 1age,childrens.name    位置
 230,a_a                position3
 330,a_b                position3
 430,b_a                position1
 532,c_a                position2
 632,c_b                position2
 732,f_a                position5
 832,f_b                position5
 933,e_a                position4
1033,e_b                position4
1140,d_a                position6

多键索引将数组里面每个元素都提取出来作为索引的 key，一旦数组的元素很多时，将会有多个 key 指向同一个文档，容易带来索引过大的问题，毕竟插入或者删除一个节点的数据，其他节点的数据将会移动或者分裂，所以需要考虑更新数组元素带来的性能消耗。

由上可以总结出，索引中 key 的数量和文档数量的比例为：

索引类别	比例
单键索引或复合索引	1:1
多键索引	N:1

以上只是简单的展示索引排序后存储的结构，真实的数据应该是以 B-Tree 的结构存放。通过索引很容易查询到符合条件的数据，可见索引的重要性。但是否索引创建越多越好呢？

慢日志之痛

在背景我们也提到，在业务高并发写入的情况，1 小时的慢日志会有 14w 之多，严重降低了数据消费速度。所以从慢日志开始这次的优化之路。

先开启 profiling 功能，此处已把需要优化的 DB 的 profiling 级别设置为 1，设置的命令为 db.setProfilingLevel(1)，默认执行时间大于 100ms 的操作命令都会被记录。

有两种方式可以查看慢日志，一种是直接查看日志文件(文件的位置和配置有关，此处是 /home/ocean/log/mongodb，每天产生一个新的日志文件)，另一张是查看 db.system.profile 这个 collection。

在开始优化前，我们先了解一下慢日志里面包含了哪些信息，从这些信息中可以看出什么问题。

慢日志的格式如下：

12019-05-16 16:35:07 10.192.xx.xx  2019-05-16T16:35:07.071+0800 I COMMAND  [conn80762] command galaxyx.cr_ipv4 command: find { find: "cr_ipv4", filter: { ip: "10.xx.xx.xx" }, projection: { _id: 1 }, limit: 1, singleBatch: true, lsid: { id: UUID("2652b715-ce8e-402c-9ff9-976b8b444dc5") }, $clusterTime: { clusterTime: Timestamp(1557995685, 2), signature: { hash: BinData(0, 1CC1672BDAEFC2EFA5DBABF9EF3A0CE3C26EEC34), keyId: 6678850264708939806 } }, $db: "xxx", $readPreference: { mode: "primary" } } planSummary: IXSCAN { ip: 1 } keysExamined:1 docsExamined:1 cursorExhausted:1 numYields:0 nreturned:1 reslen:424 locks:{ Global: { acquireCount: { r: 1 } }, Database: { acquireCount: { r: 1 }, acquireWaitCount: { r: 1 }, timeAcquiringMicros: { r: 13148462 } }, Collection: { acquireCount: { r: 1 } } } protocol:op_msg 13148ms

主要包含以下几种数据：

执行操作的类型：command，insert，query，update，remove，getmore。

执行的具体操作：如

1command: find { find: "cr_ipv4", filter: { ip: "10.xx.xx.xx" }, projection: { _id: 1 }, limit: 1, singleBatch: true, lsid: { id: UUID("2652b715-ce8e-402c-9ff9-976b8b444dc5") }, hash: BinData(0, 1CC1672BDAEFC2EFA5DBABF9EF3A0CE3C26EEC34), keyId: 6678850264708939806 } }, clusterTimeEEclusterTimeTimestampsignatureEEhashBinDataCCBDAEFCEFADBABFEFACECEECkeyIdEEEE"xxx", $readPreference: { mode: "primary" } } 2

这其中我们只关注前面执行什么命令就好，如上面执行的是 ip 过滤查询的操作。

执行计划(重要)：如

1planSummary: IXSCAN { ip: 1 } keysExamined:1 docsExamined:1 cursorExhausted:1 numYields:0 nreturned:1 reslen:424

主要关注是否命中索引，扫描的文档的数量。

锁相关的信息：

1locks:{ Global: { acquireCount: { r: 1 } }, Database: { acquireCount: { r: 1 }, acquireWaitCount: { r: 1 }, timeAcquiringMicros: { r: 13148462 } }, Collection: { acquireCount: { r: 1 } } }

如果 acquireCount 的数量很大，需要考虑读写并发量大小的问题

执行时间(重要)：13148ms

排查思路

主要优化思路如下：

先从执行时间最长的日志开始查找问题并解决
服务再次运行一段时间后，查看是否还有以上问题，如果没有减少过滤时间继续查找问题
忽略系统相关的慢日志，只关注与业务相关的慢日志

执行时间最长的日志

过滤出执行时间大于 10s 的慢日志，发现有很多查询操作是全表扫描，planSummary 为 COLLSCAN，如：

排查出所有执行全表扫描的查询，在线添加索引，这里需要注意的是，在线添加索引务必要设置为在 background 添加，默认的方式会锁表，阻塞所有的跟添加索引的表相关的读写操作，对于线上业务来说这绝对是不能接受的。

降低执行时间继续排查

解决没有添加索引导致查询全表扫描的情况后，继续运行服务一段时间，过滤日志发现已经没有了全表扫描的查询，也没有执行时间在 10s 以上的操作，mongodb 的 CPU 平均使用率也下降了一点：

但统计下来发现慢日志的数量还是很大。进一步排查，将过滤时间减少到 1s，统计后发现主要有以下三种慢日志：

与事务相关的慢日志

system session 相关的日志

与更新机器资源相关的日志

对于前面两种日志，与 mongo 本身的机制相关，暂时没法下手优化，也可能是由于更新频繁引发，如果解决掉业务相关操作的慢日志，这种慢日志是否会自己消除呢？

带着这个疑问，将优化的焦点放在第三种日志上，截图的操作是在更新机器上 docker0 这个网卡的数据，看到 planSummary 为 IXSCAN，说明查询命中了索引。我们在初始化表的时候，给 cr_resource 创建了一个唯一索引，以及众多的复合索引，因为有些复合索引的字段类型是数组，在创建索引时 mongodb 会自动转化为多键索引。对于以上日志中的查询操作，原本预想的是，会命中 {'uuid': 1, 'interface.name':1 }这个复合索引，但是命中的索引却是表的唯一索引，见图上的 planSummary：IXSCAN { uuid: 1 }。这说明 {'uuid': 1, 'interface.name':1 } 这个复合索引变成了冗余索引，查询的时候没有用到，但是在插入或者删除数据的时候，这个复合索引上的 B-Tree 部分数据将会移动，甚至会引起节点分裂，这必然会产生一定的性能消耗，如果索引数量很少，这种变动带来的性能消耗微乎其微，但冗余索引且又是多键索引的数量很多，就得令当别论了。

于是尝试将 cr_resource 的冗余索引全部去除，排查发现该表有 28 个索引，其中有 17 个冗余的复合索引，且都是多键索引，有些机器的网卡有上百个，这样子索引上的 key 和文档的比例将是 100+ ：1，可见此类多键索引的节点之多。

清除冗余索引之后的结果：CPU 使用率从最高 70% 降到 10%，如下图，优化效果明显。

让人惊喜的是，跟数据库本身机制相关的慢日志也减少了，可见这部分是受到了业务操作的影响。

总结一下此次优化过程中两个主要关注点：

找出全表扫描的查询，建立索引
删除冗余索引

疑难杂症

为什么不会命中复合索引

在 mongo shell 中执行如下的查询命令，并使用 explain 查看执行计划：

1db.cr_resource.find({'uuid': 'EC29D450-B5A9-FBE1-DD1E-xxxxxxxxxxx', 'cpu.handle': '0x0401'}).explain()

explain 结果：

预想情况下，这个查询语句应该会命中 {‘uuid’: 1, ‘cpu.handle’:1 } 这个复合索引，但从 explain 的结果可以看到，显示命中了 {‘uuid’: 1} 这个唯一索引，最后在 FETCH 阶段再过滤出符合 {'cpu.handle': '0x0401’} 的文档。

个人觉得因为查询条件需要扫描的文档数量为 1，使用唯一索引查询也可以得到相同的结果，且唯一索引的大小比 {‘uuid’: 1, ‘cpu.handle’:1 } 这个复合索引小很多，因为唯一索引上的 key 和文档是 1：1 的关系，复合索引的 key 数量可能是文档数量的几倍甚至几十倍，取决于机器上有多少同类的资源，比如这里是 CPU，如果每台机器上有 30 个 CPU(现实当然不是这样)，那么索引上 key 的数量就为 30 * 文档数，所以在唯一索引上查找到匹配文档速度会更快。

如果复合索引中没有包含唯一键，同样的查询是否会被命中呢？我们把 {‘uuid’: 1} 去掉唯一索引属性，变成一个普通的单键索引，然后插入相同的 uuid 的机器记录，相同的查询 explain 结果如下：

可见确实命中了复合索引，但仔细一想，某种程度上来说，{‘uuid’: 1} 这个索引已经变成了 {‘uuid’: 1, ‘cpu.handle’:1 } 的子集，所有只查询 uuid 的操作都可以使用后者索引，uuid 的单键索引就变成了冗余索引了。

update 操作为什么会引发高负载

cr_resource 集合里面的文档已经涵盖大部分机器的数据，后面只用进行 update 操作。对于每个集合来说，插入文档和删除文档必然会导致索引的更新，如果索引很多，会带来性能消耗，但是只是更新文档，是否也会如此呢？

如果数据库的引擎是 MMAPv1，当更新文档以至于文档的大小超出已分配的空间时，引擎就会将该文档转移到一个更大的空间存储，同时更新文档所有的索引。

但我们使用的是 wiredTiger 存储引擎，没有使用以上的存储机制，按照官方的解释，部分 update 也会触发索引更新，但此处没有发现是哪些的更新操作引发索引更新。(后面再找时间深入调研)

在优化的时候，我们还发现了一个现象，使用 db.serverStatus().globalLock 查看 cr_resource 表的锁状态的时候，发现最大写并发数(globalLock.activeClients.writers)最高接近 100，此时 mongodb CPU 使用率也达到高峰，wiredTiger 默认限制传递到引擎层面的最大读写并发数均为 128，所以有可能是并发数量过大，某些请求长时间占有锁，机器资源的更新使用事务，事务内部可能会对多个表执行读写操作，如果多个事务更新同一个表及索引，就会引发等待锁和抢占锁的问题，进一步增大 mongodb 机器的负载，在优化索引之后，写并发数最高不超过 10 个。

总结

以上我们针对 mongodb 的慢日志，梳理了优化的过程，并介绍了 mongodb 索引相关的知识，以及自己的一些见解。关于创建索引以及索引优化的一些建议：

了解业务是使用场景，有针对性地创建索引，创建过多的索引会消耗数据库的性能。
如果使用唯一键来查询，可以不用创建包含唯一键的复合索引
查询条件涵盖多个键，按照最左前缀原则创建复合索引，比如{’name’: 1, ‘age’: 1, ’tel’: 1} 可以覆盖以下查询：{'name': 'xx’, age: xx, 'tel': 'xxx'}{'name': 'xx', age: xx}{'name': 'xx'}
创建多键索引时，需要考虑数组的大小对更新索引引发的性能问题。
某个操作执行慢的时候，应考虑是否跟索引相关。
学会使用 explain 查看执行计划。

参考

WiredTiger Storage Engine
(https://docs.mongodb.com/manual/core/wiredtiger/)
Write Operation Performance
(https://docs.mongodb.com/manual/core/write-performance/#document-growth-and-the-mmapv1-storage-engine)
Effective MongoDB Indexing
(https://dzone.com/articles/effective-mongodb-indexing-part-1)
MongoDB serverStatus.globalLock 深入解析
(https://yq.aliyun.com/articles/201983)
MongoDB Indexing Best Practices
(https://www.compose.com/articles/mongodb-indexing-best-practices/)

往期精彩

NEW

﹀

KSM 应用实践

S3 的中文编码问题及修复方案

通用实时日志分类统计实践

从清档需求谈谈 Redis 二级索引的使用

Swap 与 Swappiness