目录数据库
声明:本文同步发表于 MongoDB 中文社区,传送门:
http://www.mongoing.com/archives/27310运维
最近线上的一个工单分析服务一直不大稳定,监控平台时不时发出数据库操做超时的告警。
运维兄弟沟通后,发如今天天凌晨1点都会出现若干次的业务操做失败,而数据库监控上并无发现明显的异常。
在该分析服务的日志中发现了某个数据库操做产生了 SocketTimeoutException。socket
开发同窗一开始但愿经过调整 MongoDB Java Driver 的超时参数来规避这个问题。
但通过详细分析以后,这样是没法根治问题的,并且超时配置应该如何调整也难以评估。性能
下面是关于对这个问题的分析、调优的过程。测试
从出错的信息上看,是数据库的操做响应超时了,此时客户端配置的 SocketReadTimeout 为 60s。
那么,是什么操做会致使数据库 60s 还没能返回呢?优化
业务操做翻译
左边的数据库是一个工单数据表(t_work_order),其中记录了每张工单的信息,包括工单编号(oid)、最后修改时间(lastModifiedTime)
分析服务是Java实现的一个应用程序,在天天凌晨1:00 会拉取出前一天修改的工单信息(要求按工单号排序)进行处理。
因为工单表很是大(千万级),因此在处理时会采用分页的作法(每次取1000条),使用按工单号翻页的方式:3d
db.t_work_order.find({ "lastModifiedTime":{ $gt: new Date("2019-04-09T09:44:57.106Z"), $lt: new Date("2019-04-09T10:44:57.106Z")}, "oid": {$exists: true}}) .sort({"oid":1}).limit(1000)
db.t_work_order.find({ "lastModifiedTime":{ $gt: new Date("2019-04-09T09:44:57.106Z"), $lt: new Date("2019-04-09T10:44:57.106Z")}, "oid": {$exists: true, $gt: "VXZ190"}}) .sort({"oid":1}).limit(1000)
..日志
根据这样的查询,开发人员给数据表使用的索引以下:code
db.t_work_order.ensureIndexes({ "oid" : 1, "lastModifiedTime" : -1 })
尽管该索引与查询字段基本是匹配的,但在实际执行时却表现出很低的效率:
第一次拉取时间很是的长,常常超过60s致使报错,然后面的拉取时间则会快一些
为了精确的模拟该场景,咱们在测试环境中预置了小部分数据,对拉取记录的SQL执行Explain:
db.t_work_order.find({ "lastModifiedTime":{ $gt: new Date("2019-04-09T09:44:57.106Z"), $lt: new Date("2019-04-09T10:44:57.106Z")} "oid": {$exists: true}}) .sort({"oid":1}).limit(1000) .explain("executionStats")
输出结果以下
"nReturned" : 1000, "executionTimeMillis" : 589, "totalKeysExamined" : 136661, "totalDocsExamined" : 1000, ... "indexBounds" : { "oid" : [ "[MinKey, MaxKey]" ], "lastModifiedTime" : [ "(new Date(1554806697106), new Date(1554803097106))" ] }, "keysExamined" : 136661, "seeks" : 135662,
在执行过程当中发现,检索1000条记录,竟然须要扫描 13.6 W条索引项!
其中,几乎全部的开销都花费在了 一个seeks操做上了。
官方文档对于 seeks 的解释以下:
The number of times that we had to seek the index cursor to a new position in order to complete the index scan.
翻译过来就是:
seeks 是指为了完成索引扫描(stage),执行器必须将游标定位到新位置的次数。
咱们都知道 MongoDB 的索引是B+树的实现(3.x以上),对于连续的叶子节点扫描来讲是很是快的(只须要一次寻址),那么seeks操做太多则表示整个扫描过程当中出现了大量的寻址(跳过非目标节点)。
并且,这个seeks指标是在3.4版本支持的,所以能够推测该操做对性能是存在影响的。
为了探究 seeks 是怎么产生的,咱们对查询语句尝试作了一些变动:
exists 条件的存在是由于历史问题(一些旧记录并不包含工单号的字段),为了检查exists查询是否为关键问题,修改以下:
db.t_work_order.find({ "lastModifiedTime":{ $gt: new Date("2019-04-09T09:44:57.106Z"), $lt: new Date("2019-04-09T10:44:57.106Z")} }) .sort({"oid":1}).limit(1000) .explain("executionStats")
执行后的结果为:
"nReturned" : 1000, "executionTimeMillis" : 1533, "totalKeysExamined" : 272322, "totalDocsExamined" : 272322, ... "inputStage" : { "stage" : "FETCH", "filter" : { "$and" : [ { "lastModifiedTime" : { "$lt" : ISODate("2019-04-09T10:44:57.106Z") } }, { "lastModifiedTime" : { "$gt" : ISODate("2019-04-09T09:44:57.106Z") } } ] }, ... "indexBounds" : { "oid" : [ "[MinKey, MaxKey]" ], "lastModifiedTime" : [ "[MaxKey, MinKey]" ] }, "keysExamined" : 272322, "seeks" : 1,
这里发现,去掉 exists 以后,seeks 变成了1次,但整个查询扫描了 27.2W 条索引项! 恰好是去掉以前的2倍。
seeks 变为1次说明已经使用了叶节点顺序扫描的方式,然而因为扫描范围很是大,为了找到目标记录,会执行顺序扫描并过滤大量不符合条件的记录。
在 FETCH 阶段出现了 filter可说明这一点。与此同时,咱们检查了数据表的特征:同一个工单号是存在两条记录的!因而能够说明:
除了第一次查询以外,咱们对后续的分页查询也进行了分析,以下:
db.t_work_order.find({ "lastModifiedTime":{ $gt: new Date("2019-04-09T09:44:57.106Z"), $lt: new Date("2019-04-09T10:44:57.106Z")}, "oid": {$exists: true, $gt: "VXZ190"}}) .sort({"oid":1}).limit(1000) .explain("executionStats")
上面的语句中,主要是增长了$gt: "VXZ190"这一个条件,执行过程以下:
"nReturned" : 1000, "executionTimeMillis" : 6, "totalKeysExamined" : 1004, "totalDocsExamined" : 1000, ... "indexBounds" : { "oid" : [ "(\"VXZ190\", {})" ], "lastModifiedTime" : [ "(new Date(1554806697106), new Date(1554803097106))" ] }, "keysExamined" : 1004, "seeks" : 5,
能够发现,seeks的数量很是少,并且检索过程只扫描了1004条记录,效率是很高的。
那么,是否是意味着在后面的数据中,知足查询的条件的记录很是密集呢?
为了验证这一点,咱们将一开始第一次分页的查询作一下调整,改成按工单号降序的方式(从后往前扫描):
db.t_work_order.find({ "lastModifiedTime":{ $gt: new Date("2019-04-09T09:44:57.106Z"), $lt: new Date("2019-04-09T10:44:57.106Z")}, "oid": {$exists: true}}) .sort({"oid":-1}).limit(1000) .explain("executionStats")
新的"反序查询语句"的执行过程以下:
"nReturned" : 1000, "executionTimeMillis" : 6, "totalKeysExamined" : 1001, "totalDocsExamined" : 1000, ... "direction" : "backward", "indexBounds" : { "oid" : [ "[MaxKey, MinKey]" ], "lastModifiedTime" : [ "(new Date(1554803097106), new Date(1554806697106))" ] }, "keysExamined" : 1001, "seeks" : 2,
能够看到,执行的效率更高了,几乎不须要什么 seeks 操做!
通过一番确认后,咱们获知了在全部数据的分布中,工单号越大的记录其更新时间值也越大,基本上咱们想查询的目标数据都集中在尾端。
因而就会出现一开始提到的,第一次查询很是慢甚至超时,然后面的查询就快了。
上面提到的两个查询执行路线如图所示:
经过分析,咱们知道了问题的症结在于索引的扫描范围过大,那么如何优化,以免扫描大量记录呢?
从现有的索引及条件来看,因为同时存在gt、exists以及叶子节点的时间范围限定,不可避免的会产生seeks操做,
并且查询的性能是不稳定的,跟数据分布、具体查询条件都有很大的关系。
因而一开始所提到的仅仅是增长 socketTimeout 的阈值可能只是治标不治本,一旦数据的索引值分布变化或者数据量持续增大,可能会发生更严重的事情。
回到一开始的需求场景,定时器要求读取天天更新的工单(按工单号排序),再进行分批处理。
那么,按照化零为整的思路,新增一个lastModifiedDay字段,这个存储的就是lastModifiedTime对应的日期值(低位取整),这样在同一天内更新的工单记录都有一样的值。
创建组合索引 {lastModifiedDay:1, oid:1},相应的查询条件改成:
{ "lastModifiedDay": new Date("2019-04-09 00:00:00.000"), "oid": {$gt: "VXZ190"} } -- limit 1000
执行结果以下:
"nReturned" : 1000, "executionTimeMillis" : 6, "totalKeysExamined" : 1000, "totalDocsExamined" : 1000, ... "indexBounds" : { "lastModifiedDay" : [ "(new Date(1554803000000), new Date(1554803000000))" ], "oid" : [ "(\"VXZ190\", {})" ] }, "keysExamined" : 1000, "seeks" : 1,
这样优化以后,每次查询最多只扫描1000条记录,查询速度是很是快的!
本质上,这就是一种空间换时间的方法,即经过存储一个额外的索引字段来加速查询,经过增长少许的存储开销提高了总体的效能。 在对于许多问题进行优化时,常常是须要从应用场景触发,适当的转换思路。 好比在本文的问题中,是否是必定要增长字段呢?若是业务上能够接受不按工单号排序进行读取,那么仅使用更新时间字段进行分页拉取也是能够达到效果的,具体仍是要由业务场景来定。