背景介绍
案例分析
基于上述问题,某些用户在读取备节点时,可能遇到因为 Secondary 重放 oplog 占用特殊锁时间较长,导致读取的延时变长。
问题1:单个请求耗时长
一个长达1小时的『前台创建索引』请求,在 Secondary 节点上重放时,一直占用 ParallelBatchWriterMode
锁,导致 Secondary 上所有请求阻塞长达1小时,这个案例我在Secondary节点为何阻塞请求近一个小时? 里已经分析过,这里不再赘述,解决方案是尽量后台建索引。
上述场景除了会影响 Secondary 上的读请求,如果 Priamry 上写请求指定了 writeConcern 来写多个节点({w: 2+}),而 Secondary 又一直阻塞在创建索引上,导致其后的oplog 重放都要等待创建索引结束,从而主上的写入也阻塞。
问题2:多个请求加起来耗时长
当主上写入并发很大时,Secondary 每次能拉到很多条 oplog,然后并发重放,重放一条的耗时可能很小,但累计起来一次重放上百、上千条 oplog,耗时就会高很多,而重放过程中,Secondary 上读请求都是要阻塞等待的,所以总体看上去,「Secondary 上平均延时,可能比 Primary 上更长点」(这就是为什么很多用户在写入比较多时,会发现读secondary 比 读praimry 更慢),但只要延时在可接受范围内,这个问题并无影响,而且根据云上用户使用的经验,绝大部分用户都是感受不到这个差异的。
但有一种情况值要注意

从上面的例子可以看到,一条 update 操作,指定了 {multi: true} 选项,更新了2个匹配的文档,针对每个文档都产生了一条 oplog(主要为了保证 oplog 幂等性),如果匹配的文档有成千上万条,就会产生对应数量的 oplog,然后 Secondary 拉取这些 oplog 并重放;这个场景下,update 的开销在Secondary 上被放大多倍,此时Secondary 的读延时可能会受比较大的影响。
如何评估重放 oplog 时锁的影响有多大?
从上述的例子可以看出,Secondary 在某些场景下会出现读延时很高的情况,那么当实际遇到问题时,如何判断问题就是 Secondary 重放 oplog 占用锁时间太长导致呢?
我们的做法是增加审计日志,把『Secondary 节点重放每一批 oplog 的时间开销记录到审计日志』里,这样就能很方便的看出影响到底有多大,如下是一个『简化版本的加日志的patch』,有需要的可以应用到 MongoDB 3.2上。
diff --git a/src/mongo/db/repl/sync_tail.cpp b/src/mongo/db/repl/sync_tail.cpp
index 50517c2..e7d58bc 100644
--- a/src/mongo/db/repl/sync_tail.cpp
+++ b/src/mongo/db/repl/sync_tail.cpp
@@ -550,6 +550,8 @@ OpTime SyncTail::multiApply(OperationContext* txn,
// stop all readers until we're done
Lock::ParallelBatchWriterMode pbwm(txn->lockState());
+ unsigned long long startTime = curTimeMicros64();
+
if (inShutdownStrict()) {
log() << "Cannot apply operations due to shutdown in progress";
return OpTime();
@@ -585,6 +587,8 @@ OpTime SyncTail::multiApply(OperationContext* txn,
setMinValid(txn, boundaries->end, DurableRequirement::None); // Mark batch as complete.
}
+ log() << "batch writer cost " << (curTimeMicros64() - startTime) << us;
+
return lastOpTime;
}
参考资料