看到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个动作导致。
背景知识
- Secondary从Primary拉取到一批oplog后，重放oplog的过程会加一把特殊的锁，这个锁会阻塞所有的reader，这么做的原因我个人理解是避免让reader看到中间状态，只有等一批oplog全部应用成功才让客户端可读，避免出现脏读的问题。
- 建索引有前台（foreground）和后台（background）2种模式，前台建索引会加在整个过程中对DB加互斥写锁，同一个DB下的读写操作均会阻塞至索引建立结束；后台建索引只会对DB加意向写锁，对DB下的读写无影响。
- Secondary重放建立索引的命令时，如果是前台模式，则整个重放建索引的过程都会阻塞所有的reader；如果是后台模式，重放时建索引的动作会放到后台线程里做，只会阻塞reader很短的时间。
为了尽量避免建索引影响业务，通常
- 在集合创建的时候，就建立好索引，此时因为集合为空，建索引的开销很小。（以后每次写入，同时会更新索引）
- 如果建索引时，集合内已经写入了很多文档，尽量使用后台模式，避免『主节点上影响某个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结束，开始应答阻塞的请求|
- 15:07:00 Primary上发起后台建索引，创建索引的过程耗费近1.5小时
- 16:32:25 创建索引完成，Primary上记录oplog，Secondary拉取到oplog并重放该动作，由于是后台建索引，Secondary会启动一个单独的线程来建索引，建索引的过程会对DB加意向锁，所以重放动作只会阻塞reader很短的时间（毫秒级别）。
- 16:54:53 用户在同一个DB下发起了一个删除索引的动作，删除动作在主上很快结束，备拉取到oplog开始重放，删除索引的动作需要对DB加互斥锁，而此时Secondary后台建索引还在进行中，已经对DB加了意向锁，导致这个互斥锁需要等待后台建索引结束，而重放oplog时，Secondary占用的特殊锁会阻塞所有的reader，所以从这个时间点开始，所有的reader都阻塞等待了。
- 17:54:53 Secondary后台建索引结束，删除索引获得互斥锁并完成删除动作，重放结束，阻塞的reader加锁成功并得到处理。
总结
上述问题主要因为MongoDB的设计机制导致，Secondary节点重放oplog时的锁粒度太大，会阻塞所有的读请求；但如果降低锁粒度，就可能会出现脏读的问题，这对于某些业务场景是不可接受的。目前来说，只要不把『耗时长并且需要同步到备节点』的操作放到业务逻辑里，影响是完全可以忽略的，如果实在无法避免，最终出现了Secondary长时间阻塞的情况，就直接使用默认的readPreference，只从Primary上读数据。
参考资料
