MongoDB-系統時鐘跳變引發的風波

• 2019 年 10 月 27 日
• 筆記

聲明：本文同步發表於 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")          }  }  

欄位說明

關於 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 版本經驗證已經解決。

那麼，為了最大限度降低影響，提供幾點建議：

1. 分散式集群中務必採用可靠的NTP服務保證各節點上的時間同步，對於時間同步做好告警檢測並保證能及時解決異常；
2. 重大的時間校準，採用小步長(比如1分鐘內3-5s)的方式逐步漸漸達到最終同步，這樣可以避免主備切換產生的業務影響。
3. 升級到3.6/4.0 或更新的版本來規避時間跳變導致選舉的問題。