時間跳變對副本集有什么影響

背景

在生產環境的部署中,由于各種不確定因素的存在(比如機器掉電、網絡延遲等),各節點上的系統時間很可能會出現不一致的情況。
對于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字段不斷進行增量拉取,來達到同步的目的。

timechange-oplog
圖-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( 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機制,如下:

timechange-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::scheduleWorkAt(
    Date_t when, const CallbackFn& work) {
    stdx::lock_guard lk(_mutex);
    WorkQueue temp;
    StatusWith 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 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 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 或更新的版本來規避時間跳變導致選舉的問題。

關于zale

唐卓章,華為技術專家,多年互聯網研發/架設經驗,關注NOSQL 中間件高可用及彈性擴展,在分布式系統架構性能優化方面有豐富的實踐經驗,目前從事物聯網平臺研發工作,致力于打造大容量高可用的物聯網服務。

發表評論