Secondary节点为何阻塞请求近一个小时?

看到Secondary节点上的日志,我的内心的崩溃的,鉴权请求居然耗时2977790ms(约50分钟),经详细统计,这个Secondary节点上,所有16:54之后发起的用户请求,都阻塞到17:54左右才返回,处理时间最长的请求约1个小时。

2016-06-17T17:54:57.575+0800 I COMMAND  [conn2581] command admin.system.users command: saslStart { saslStart: 1, mechanism: "SCRAM-SHA-1", payload: "xxx" } keyUpdates:0 writeConflicts:0 numYields:0 reslen:171 locks:{ Global: { acquireCount: { r: 2 } }, Database: { acquireCount: { r: 1 } }, Collection: { acquireCount: { r: 1 } } } protocol:op_query 2977790ms
2016-06-17T17:54:57.575+0800 I COMMAND  [conn2740] command admin.system.users command: saslStart { saslStart: 1, mechanism: "SCRAM-SHA-1", payload: "xxx" } keyUpdates:0 writeConflicts:0 numYields:0 reslen:171 locks:{ Global: { acquireCount: { r: 2 } }, Database: { acquireCount: { r: 1 } }, Collection: { acquireCount: { r: 1 } } } protocol:op_query 2416390ms

经过调查,引发备节点阻塞近1个小时主要是对一个很大的集合『后台建立索引 + 删除索引』2个动作导致。

背景知识

  1. Secondary从Primary拉取到一批oplog后,重放oplog的过程会加一把特殊的锁,这个锁会阻塞所有的reader,这么做的原因我个人理解是避免让reader看到中间状态,只有等一批oplog全部应用成功才让客户端可读,避免出现脏读的问题。
  2. 建索引有前台(foreground)和后台(background)2种模式,前台建索引会加在整个过程中对DB加互斥写锁,同一个DB下的读写操作均会阻塞至索引建立结束;后台建索引只会对DB加意向写锁,对DB下的读写无影响。
  3. Secondary重放建立索引的命令时,如果是前台模式,则整个重放建索引的过程都会阻塞所有的reader;如果是后台模式,重放时建索引的动作会放到后台线程里做,只会阻塞reader很短的时间。

为了尽量避免建索引影响业务,通常

  1. 在集合创建的时候,就建立好索引,此时因为集合为空,建索引的开销很小。(以后每次写入,同时会更新索引)
  2. 如果建索引时,集合内已经写入了很多文档,尽量使用后台模式,避免『主节点上影响某个DB的所有读写』以及『备节点上影响所有的读』。

问题分析

在我们遇到的问题里,创建索引使用的后台模式,最终仍然导致Secondary阻塞读reader近1个小时,接下来分析下问题产生的原因,主要事件的过程如下所示。

time Primary Secondary
15:07:00 db.coll 开始后台创建索引
16:32:35 db.coll 创建索引结束 从oplog拉取到createIndex的操作,并开始重放
16:54:53 删除db数据库下某个索引 从oplog拉取到dropIndex的请求并开始重放,此时所有的请求开始阻塞
17:54:53 重放createIndex结束,开始应答阻塞的请求
  1. 15:07:00 Primary上发起后台建索引,创建索引的过程耗费近1.5小时
  2. 16:32:25 创建索引完成,Primary上记录oplog,Secondary拉取到oplog并重放该动作,由于是后台建索引,Secondary会启动一个单独的线程来建索引,建索引的过程会对DB加意向锁,所以重放动作只会阻塞reader很短的时间(毫秒级别)。
  3. 16:54:53 用户在同一个DB下发起了一个删除索引的动作,删除动作在主上很快结束,备拉取到oplog开始重放,删除索引的动作需要对DB加互斥锁,而此时Secondary后台建索引还在进行中,已经对DB加了意向锁,导致这个互斥锁需要等待后台建索引结束,而重放oplog时,Secondary占用的特殊锁会阻塞所有的reader,所以从这个时间点开始,所有的reader都阻塞等待了。
  4. 17:54:53 Secondary后台建索引结束,删除索引获得互斥锁并完成删除动作,重放结束,阻塞的reader加锁成功并得到处理。

总结

上述问题主要因为MongoDB的设计机制导致,Secondary节点重放oplog时的锁粒度太大,会阻塞所有的读请求;但如果降低锁粒度,就可能会出现脏读的问题,这对于某些业务场景是不可接受的。目前来说,只要不把『耗时长并且需要同步到备节点』的操作放到业务逻辑里,影响是完全可以忽略的,如果实在无法避免,最终出现了Secondary长时间阻塞的情况,就直接使用默认的readPreference,只从Primary上读数据。

参考资料

作者简介

张友东,阿里巴巴技术专家,主要关注分布式存储、Nosql数据库等技术领域,先后参与TFS(淘宝分布式文件系统)Redis云数据库等项目,目前主要从事MongoDB云数据库的研发工作,致力于让开发者用上最好的MongoDB云服务。

发表评论