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

時間 2019-11-06

原文原文鏈接

目錄mongodb

聲明：本文同步發表於 MongoDB 中文社區，傳送門：
http://www.mongoing.com/archives/26201shell

背景

在生產環境的部署中，因爲各類不肯定因素的存在(好比機器掉電、網絡延遲等)，各節點上的系統時間極可能會出現不一致的狀況。
對於MongoDB來講，時間不一致會對數據庫的運行帶來一些不可預估的風險，好比主從複製、定時調度都或多或少依賴於時間的取值及判斷。數據庫

所以，在MongoDB集羣中保持節點間的時間同步是一項重要的任務，這一般會使用一些NTP協調服務來實現。
經過人工執行的時間設定操做，或是NTP同步觸發的校準，都會使當前的系統時間發生變化，這稱之爲時間跳變。
時間跳變對於正在運做的流程是存在影響的，尤爲是副本集的複製、心跳機制。安全

接下來，將針對這些影響作一些分析。網絡

1、對 oplog 的影響

oplog 原理

oplog 是主從數據複製的紐帶，主節點負責將寫入數據變動記錄寫入到 oplog 集合，備節點則負責從oplog 中拉取增量的記錄進行回放。架構

一個典型的 oplog以下所示：app

{
        "ts" : Timestamp(1560861342, 2),
        "t" : NumberLong(12),
        "h" : NumberLong("7983167552279045735"),
        "v" : 2,
        "op" : "d",
        "ns" : "app.T_AppInfo",
        "o" : {
                "_id" : ObjectId("5d08da9ebe3cb8c01ea48a25")
        }
}

字段說明dom

字段名	字段描述
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的時間。

2、主備倒換

在副本集的高可用架構中，提供了一種自動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 版本經驗證已經解決。

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