MongoDB-系統時鐘跳變引發的風波
目錄
- 背景
- 一、 對 oplog 的影響
- oplog 原理
- 二、主備倒換
- 小結
宣告：本文同步發表於 MongoDB 中文社群，傳送門：
http://www.mongoing.com/archives/26201
背景
在生產環境的部署中，由於各種不確定因素的存在(比如機器掉電、網路延遲等)，各節點上的系統時間很可能會出現不一致的情況。
對於MongoDB來說，時間不一致會對資料庫的執行帶來一些不可預估的風險，比如主從複製、定時排程都或多或少依賴於時間的取值及判斷。
因此，在MongoDB叢集中保持節點間的時間同步是一項重要的任務，這通常會使用一些NTP協調服務來實現。
通過人工執行的時間設定操作，或是NTP同步觸發的校準，都會使當前的系統時間發生變化，這稱之為時間跳變。
時間跳變對於正在運作的流程是存在影響的，尤其是副本集的複製、心跳機制。
接下來，將針對這些影響做一些分析。
一、 對 oplog 的影響
oplog 原理
oplog 是主從資料複製的紐帶，主節點負責將寫入資料變更記錄寫入到 oplog 集合，備節點則負責從oplog 中拉取增量的記錄進行回放。
一個 典型的 oplog如下所示：
{ "ts" : Timestamp(1560861342, 2), "t" : NumberLong(12), "h" : NumberLong("7983167552279045735"), "v" : 2, "op" : "d", "ns" : "app.T_AppInfo", "o" : { "_id" : ObjectId("5d08da9ebe3cb8c01ea48a25") } }
欄位說明
| 欄位名 | 欄位描述 |
|---|---|
| ts | 記錄時間 |
| h | 記錄的全域性唯一標識 |
| v | 版本資訊 |
| op | 操作型別(增刪改查等) |
| ns | 操作的集合 |
| o | 操作內容 |
| o2 | 待更新的文件，僅 update 操作包含 |
關於 oplog 的結構可以參考這篇文章
其中，ts欄位 實現日誌拉取的關鍵，這個欄位保證了 oplog是節點有序的，它的構成如下：
- 當前的系統時間，即UNIX時間至現在的秒數，32位
- 整數計時器，不同時間值會將計數器進行重置，32位
ts欄位屬於Bson的Timestamp型別，這種型別一般在 MongoDB內部使用。
既然 oplog 保證了節點有序，備節點便可以通過輪詢的方式進行拉取，我們通過 db.currentOp()命令可以看到具體的實現：
db.currentOp({"ns" : "local.oplog.rs"})
>
{
"desc" : "conn611866",
"client" : "192.168.138.77:51842",
"clientMetadata" : {
"driver" : {
"name" : "NetworkInterfaceASIO-RS",
"version" : "3.4.10"
}
},
"active" : true,
"opid" : 20648187,
"secs_running" : 0,
"microsecs_running" : NumberLong(519601),
"op" : "getmore",
"ns" : "local.oplog.rs",
"query" : {
"getMore" : NumberLong("16712800432"),
"collection" : "oplog.rs",
"maxTimeMS" : NumberLong(5000),
"term" : NumberLong(2),
"lastKnownCommittedOpTime" : {
"ts" : Timestamp(1560842637, 2),
"t" : NumberLong(2)
}
},
"originatingCommand" : {
"find" : "oplog.rs",
"filter" : {
"ts" : {
"$gte" : Timestamp(1560406790, 2)
}
},
"tailable" : true,
"oplogReplay" : true,
"awaitData" : true,
"maxTimeMS" : NumberLong(60000),
"term" : NumberLong(2),
"readConcern" : {
"afterOpTime" : {
"ts" : Timestamp(1560406790, 2),
"t" : NumberLong(1)
}
}
},
"planSummary" : "COLLSCAN",
}
可見，副本集的備節點是通過 ts欄位不斷進行增量拉取，來達到同步的目的。
圖-oplog 拉取
接下來，看一下oplog與系統時間的對應關係，先通過mongo shell 寫入一條資料，檢視生成的oplog
shard0:PRIMARY> db.test.insert({"justForTest": true})
shard0:PRIMARY> db.getSiblingDB("local").oplog.rs.find({ns: "test.test"}).sort({$natural: -1}).limit(1).pretty()
{
"ts" : Timestamp(1560842490, 2),
"t" : NumberLong(2),
"h" : NumberLong("-1966048951433407860"),
"v" : 2,
"op" : "i",
"ns" : "test.test",
"o" : {
"_id" : ObjectId("5d088723b0a0777f7326df57"),
"justForTest" : true
}
}此時的 ts=Timestamp(1560842490, 2)，將它轉換為可讀的時間格式：
shard0:PRIMARY> new Date(1560842490*1000)
ISODate("2019-06-18T07:21:30Z")同時，我們檢視系統當前的時間，可以確定 oplog的時間戳與系統時間一致。
# date '+%Y-%m-%d %H:%M:%S'
2019-06-18 07:21:26接下來，測試時間跳變對於oplog的影響
由於 oplog 是主節點產生的，下面的測試都基於主節點進行
A. 時間向後跳變
在主節點上將時間往後調整到 9:00，如下：
# date -s 09:00:00
Tue Jun 18 09:00:00 UTC 2019寫入一條測試資料，檢查oplog的時間戳：
shard0:PRIMARY> db.test.insert({"justForTest": true})
shard0:PRIMARY> db.getSiblingDB("local").oplog.rs.find({ns: "test.test"}).sort({$natural: -1}).limit(1).pretty()
{
"ts" : Timestamp(1560848723, 1),
"t" : NumberLong(4),
"h" : NumberLong("-6994951573635880200"),
"v" : 2,
"op" : "i",
"ns" : "test.test",
"o" : {
"_id" : ObjectId("5d08a953b9963dbc8476d6b7"),
"justForTest" : true
}
}
shard0:PRIMARY> new Date(1560848723*1000)
ISODate("2019-06-18T09:05:23Z")可以發現，隨著系統時間往後調整之後，oplog的時間戳也發生了同樣的變化。
B. 時間向前跳變
繼續這個測試，這次在主節點上將時間往前調整到 7:00，如下：
host-192-168-138-148:~ # date -s 07:00:00
Tue Jun 18 07:00:00 UTC 2019寫入一條測試資料，檢查oplog的時間戳：
shard0:PRIMARY> db.test.insert({"justForTest": true})
shard0:PRIMARY> db.getSiblingDB("local").oplog.rs.find({ns: "test.test"}).sort({$natural: -1}).limit(1).pretty()
{
"ts" : Timestamp(1560848864, 92),
"t" : NumberLong(4),
"h" : NumberLong("3290816976088149103"),
"v" : 2,
"op" : "i",
"ns" : "test.test",
"o" : {
"_id" : ObjectId("5d088c1eb9963dbc8476d6b8"),
"justForTest" : true
}
}
shard0:PRIMARY> new Date(1560848864*1000)
ISODate("2019-06-18T09:07:44Z")問題出現了，當時間向前跳變的時候，新產生的oplog時間戳並沒有如預期一樣和系統時間保持一致，而是停留在了時間跳變前的時刻！
這是為什麼呢？
我們在前面提到過，oplog需要保證節點有序性，這分別是通過Unix時間戳(秒)和計數器來保證的。
因此，當系統時間值突然變小，就必須將當前時刻凍結住，通過計數器(Term)自增來保證順序。
這樣就解釋了oplog時間戳停頓的問題，然而，新問題又來了：
計數器是有上限的，如果時間向前跳變太多，或者是一直向前跳變，導致計數器溢位怎麼辦呢？
從保證有序的角度上看，這是不被允許的，也就是當計數器(Term)溢位後將再也無法保證有序了。
從MongoDB 3.4的原始碼中，可以看到對應的實現如下：
global_timestamp.cpp
//獲取下一個時間戳
Timestamp getNextGlobalTimestamp(unsigned count) {
//系統時間值
const unsigned now = durationCount<Seconds>(
getGlobalServiceContext()->getFastClockSource()->now().toDurationSinceEpoch());
...
// 對當前上下文的Timestamp 自增計數
auto first = globalTimestamp.fetchAndAdd(count);
auto currentTimestamp = first + count; // What we just set it to.
unsigned globalSecs = Timestamp(currentTimestamp).getSecs();
// 若上下文時間大於系統時間，且同一時刻的計數器 超過2^31-1(2147483647)時，進行報錯
if (MONGO_unlikely(globalSecs > now) && Timestamp(currentTimestamp).getInc() >= 1U << 31) {
mongo::severe() << "clock skew detected, prev: " << globalSecs << " now: " << now;
fassertFailed(17449);
}從程式碼上看，計數器在超過21億後會發生溢位，該時間視窗的計算參考如下：
假設資料庫吞吐量是1W/s，不考慮資料均衡等其他因素的影響，每秒鐘將需要產生1W次oplog，那麼視窗值為：
(math.pow(2,31)-1)/10000/3600 = 59h
也就是說，我們得保證系統時間能在59個小時內追趕上最後一條oplog的時間。
二、主備倒換
在副本集的高可用架構中，提供了一種自動Failover機制，如下：
圖-Failover
簡單說就是節點之間通過心跳感知彼此的存在，一旦是備節點感知不到主節點，就會重新選舉。
在實現上，備節點會以一定間隔(大約2s)向其他節點發送心跳，同時會啟動一個選舉定時器，這個定時器是實現故障轉移的關鍵：
- 選舉定時器的預設時間被設為10s(實際值為10-12s之間)，
- 在定時器時間到達時會觸發一個回撥函式，這個函式中備節點會主動發起選舉，並接管主節點的角色。
- 每次向主節點心跳成功後都會取消選舉定時器的執行，並重新發起新的選舉定時器
因此，在正常情況下主節點一直是可用的，選舉定時器回撥會被一次次的取消，而只有在異常的情況下，備節點才會主動進行"奪權"，進而發生主備切換。
那麼，接著上面的問題，系統時間的跳變是否會影響這個機制呢？我們來做一下測試：
自動Failover的邏輯由備節點主導，因此下面的測試都基於備節點進行
A. 時間向前跳變
我們在備節點上將時間調前一個小時，如下：
# date
Tue Jun 18 09:00:12 UTC 2019
# date -s 08:00:00
Tue Jun 18 08:00:00 UTC 2019然後通過db.isMaster()檢查主備的關係：
shard0:SECONDARY> db.isMaster()
{
"hosts" : [
"192.168.138.77:30071",
"192.168.138.148:30071",
"192.168.138.55:30071"
],
"setName" : "shard0",
"setVersion" : 1,
"ismaster" : false,
"secondary" : true,
"primary" : "192.168.138.148:30071",
"me" : "192.168.138.55:30071",
...
"readOnly" : false,
"ok" : 1
}
=== 沒有發生變化，仍然是備節點
shard0:SECONDARY>結果是在時間往前調整後，主備關係並沒有發生變化，從日誌上也沒有發現任何異常。
B. 時間向後跳變
接下來，在這個備節點上將時間往後調一個小時，如下：
# date
Tue Jun 18 08:02:45 UTC 2019
# date -s 09:00:00
Tue Jun 18 09:00:00 UTC 2019
這時候進行檢查則發現了變化，當前的備節點成為了主節點！
shard0:SECONDARY> db.isMaster()
{
"hosts" : [
"192.168.138.77:30071",
"192.168.138.148:30071",
"192.168.138.55:30071"
],
"setName" : "shard0",
"setVersion" : 1,
"ismaster" : true,
"secondary" : false,
"primary" : "192.168.138.55:30071",
"me" : "192.168.138.55:30071",
"electionId" : ObjectId("7fffffff0000000000000008"),
...
"readOnly" : false,
"ok" : 1
}
=== 發生變化，切換為主節點
shard0:PRIMARY>在資料庫日誌中，同樣發現了發起選舉的行為，如下：
I REPL [ReplicationExecutor] Starting an election, since we've seen no PRIMARY in the past 10000ms
I REPL [ReplicationExecutor] conducting a dry run election to see if we could be elected
I REPL [ReplicationExecutor] VoteRequester(term 7 dry run) received a yes vote from 192.168.138.77:30071; response message: { term: 7, voteGranted: true, reason: "", ok: 1.0 }
I REPL [ReplicationExecutor] dry election run succeeded, running for election
I REPL [ReplicationExecutor] VoteRequester(term 8) received a yes vote from 192.168.138.77:30071; response message: { term: 8, voteGranted: true, reason: "", ok: 1.0 }
I REPL [ReplicationExecutor] election succeeded, assuming primary role in term 8
I REPL [ReplicationExecutor] transition to PRIMARY
I REPL [ReplicationExecutor] Entering primary catch-up mode.
I REPL [ReplicationExecutor] Caught up to the latest optime known via heartbeats after becoming primary.
I REPL [ReplicationExecutor] Exited primary catch-up mode.
I REPL [rsBackgroundSync] Replication producer stopped after oplog fetcher finished returning a batch from our sync source. Abandoning this batch of oplog entries and re-evaluating our sync source.
I REPL [SyncSourceFeedback] SyncSourceFeedback error sending update to 192.168.138.148:30071: InvalidSyncSource: Sync source was cleared. Was 192.168.138.148:30071
I REPL [rsSync] transition to primary complete; database writes are now permitted
I REPL [ReplicationExecutor] Member 192.168.138.148:30071 is now in state SECONDARY確實，在備節點的系統時間往後跳變時，發生了主備切換！
那麼問題出在哪裡？ 是不是隻要是時間往後調整就一定會切換呢？
下面，我們嘗試從3.4的原始碼中尋求答案：
選舉定時器是由 ReplicationCoordinatorImpl這個類實現的，看下面這個方法：
程式碼位置：db/repl/replication_coordinator_impl_heartbeat.cpp***
void ReplicationCoordinatorImpl::_cancelAndRescheduleElectionTimeout_inlock() {
//如果上一個定時器回撥存在，則直接取消
if (_handleElectionTimeoutCbh.isValid()) {
_replExecutor.cancel(_handleElectionTimeoutCbh);
..
}
...
//觸發排程，when時間點為 now + electionTimeout + randomOffset
//到了時間就執行_startElectSelfIfEligibleV1函式，發起選舉
_handleElectionTimeoutCbh =
_scheduleWorkAt(when,
stdx::bind(&ReplicationCoordinatorImpl::_startElectSelfIfEligibleV1,this,
StartElectionV1Reason::kElectionTimeout));
}ReplicationExecutor::_scheduleWorkAt 是定時器排程的入口，負責將定時器回撥任務寫入佇列，如下：
程式碼位置：db/repl/replication_executor.cpp
StatusWith<ReplicationExecutor::CallbackHandle> ReplicationExecutor::scheduleWorkAt(
Date_t when, const CallbackFn& work) {
stdx::lock_guard<stdx::mutex> lk(_mutex);
WorkQueue temp;
StatusWith<CallbackHandle> cbHandle = enqueueWork_inlock(&temp, work);
...
WorkQueue::iterator insertBefore = _sleepersQueue.begin();
//根據排程時間找到插入位置
while (insertBefore != _sleepersQueue.end() && insertBefore->readyDate <= when)
++insertBefore;
//將任務置入_sleepersQueue佇列
_sleepersQueue.splice(insertBefore, temp, temp.begin());
...
return cbHandle;
}
對於佇列任務的處理是在主執行緒實現的，通過getWork方法迴圈獲取任務後執行：
//執行執行緒 -- 持續獲取佇列任務
void ReplicationExecutor::run() {
...
//迴圈獲取任務執行
while ((work = getWork()).first.callback.isValid()) {
//發起任務..
}
}
//獲取可用的任務
ReplicationExecutor::getWork() {
stdx::unique_lock<stdx::mutex> lk(_mutex);
while (true) {
//取當前時間
const Date_t now = _networkInterface->now();
//將_sleepersQueue佇列中到時間的任務置入_readyQueue佇列(喚醒)
Date_t nextWakeupDate = scheduleReadySleepers_inlock(now);
//存在任務執行，跳出迴圈
if (!_readyQueue.empty()) {
break;
} else if (_inShutdown) {
return std::make_pair(WorkItem(), CallbackHandle());
}
lk.unlock();
//沒有合適的任務，繼續等待
if (nextWakeupDate == Date_t::max()) {
_networkInterface->waitForWork();
} else {
_networkInterface->waitForWorkUntil(nextWakeupDate);
}
lk.lock();
}
//返回待執行任務
const WorkItem work = *_readyQueue.begin();
return std::make_pair(work, cbHandle);
}
//將到時間的任務喚醒，寫入_readyQueue佇列
Date_t ReplicationExecutor::scheduleReadySleepers_inlock(const Date_t now) {
WorkQueue::iterator iter = _sleepersQueue.begin();
//從頭部開始，找到最後一個排程時間小於等於當前時間(需要執行)的任務
while ((iter != _sleepersQueue.end()) && (iter->readyDate <= now)) {
auto callback = ReplicationExecutor::_getCallbackFromHandle(iter->callback);
callback->_isSleeper = false;
++iter;
}
//轉移佇列
_readyQueue.splice(_readyQueue.end(), _sleepersQueue, _sleepersQueue.begin(), iter);
if (iter == _sleepersQueue.end()) {
// indicate no sleeper to wait for
return Date_t::max();
}
return iter->readyDate;
}
從上面的程式碼中，可以看到 scheduleReadySleepers_inlock 方法是關於任務執行時機判斷的關鍵，在它的實現邏輯中，會根據任務排程時間與當前時間(now)的比對來決定是否執行。
關於當前時間(now)的獲取則來自於AsyncTimerFactoryASIO的一個方法，當中則是利用 asio庫的system_timer獲取了系統時鐘。
至此，我們基本可以確定了這個情況：
由於系統時間向後跳變，會導致定時器的排程出現誤判，其中選舉定時器被提前執行了！
更合理的一個實現應該是採用硬體時鐘的週期而不是系統時間。
那麼，剩下的一個問題是，系統時間是不是一旦向後跳就會出現切換呢？
根據前面的分析，每次心跳成功後都會啟用這個選舉定時器，觸發的時間被設定在10-12s之後，而心跳的間隔是2s，
於是我們可以估算如下：
如果系統時間往後跳的步長能控制在 8s以內則是安全的，而一旦超過12s則一定會觸發切換。
下面是針對步長測試的一組結果：
//往後切2s
date -s `date -d "2 second" +"%H:%M:%S"`
>> 結果：主備不切換
//往後切5s
date -s `date -d "5 second" +"%H:%M:%S"`
>> 結果：主備不切換
//往後切7s
date -s `date -d "7 second" +"%H:%M:%S"`
>> 結果：主備不切換
//往後切10s
date -s `date -d "10 second" +"%H:%M:%S"`
>> 結果：主備偶爾切換
//往後切13s
date -s `date -d "13 second" +"%H:%M:%S"`
>> 結果：主備切換
//往後切20s
date -s `date -d "20 second" +"%H:%M:%S"`
>> 結果：主備切換
小結
經過上面的一些測試和分析，我們知道了時間跳變對於副本集確實會造成一些問題：
- 對於oplog複製的影響，時間向前跳變會導致出現"計時器堆積"，如果未及時處理，將導致溢位從而引發錯誤；
- 對於自動Failover的影響，時間向後跳變則會造成干擾，很可能導致主備切換及業務的抖動。
尤其是第二點，MongoDB 3.4及以下版本都會存在該問題，而3.6/4.0 版本經驗證已經解決。
那麼，為了最大限度降低影響，提供幾點建議：
- 分散式叢集中務必採用可靠的NTP服務保證各節點上的時間同步，對於時間同步做好告警檢測並保證能及時解決異常；
- 重大的時間校準，採用小步長(比如1分鐘內3-5s)的方式逐步漸漸達到最終同步，這樣可以避免主備切換產生的業務影響。
- 升級到3.6/4.0 或更新的版本來規避時間跳變導致選舉的問題。