一、先說結(jié)論
如果您的StarRocks版本在3.1.4及以下，并且使用了metadata_journal_skip_bad_journal_ids來跳過某個異常的journal，結(jié)果之后就出現(xiàn)了FE的元數(shù)據(jù)無法進(jìn)行Checkpoint的現(xiàn)象，那么選擇升級版本到3.1.4以上，就可以解決。
二、背景
已經(jīng)平穩(wěn)運行了幾個月的StarRocks集群突然奔潰，在恢復(fù)過程中，發(fā)現(xiàn)其元數(shù)據(jù)從5月16號之后一直沒有進(jìn)行過合并，導(dǎo)致BDB文件非常多，其恢復(fù)時間達(dá)到了將近2小時。
現(xiàn)象：
- 查看FE的meta/image下面的image文件的生成時間，發(fā)現(xiàn)為2024.5.16。
- 查詢FE的meta/bdb目錄下的.jdb文件數(shù)量的數(shù)量到達(dá)了8000多個，大小到了81G。
- 每次FE恢復(fù)元數(shù)據(jù)重放需要將近2小時小時。
三、排查原因
通過現(xiàn)象已經(jīng)明確了其沒有做Checkpoint操作，導(dǎo)致image文件一直沒有更新，那么首先想到兩個可能：
一是由于某些原因一直沒有觸發(fā)元數(shù)據(jù)的CheckPoint操作。
二是進(jìn)行了CheckPoint的操作，但是由于某些原因，Checkpoint操作一直無法成功。
于是準(zhǔn)備在日志中找相關(guān)的佐證。于是開始查詢查看源碼,查看進(jìn)行Checkpoint操作的類Checkpoint.java(路徑：fe/fe-core/src/main/java/com/starrocks/leader/Checkpoint.java)，從下面的源碼中可以看出，在replayAndGenerateGlobalStateMgrImage方法中，可以看到進(jìn)行Checkpoint操作時其打印了相關(guān)日志，于是在fe的相關(guān)日志中查詢是否輸出了這些日志信息，根據(jù)其是否出現(xiàn)，可以判定是否做了Checkpoint操作，并且Checkpoint操作是否成功。
private boolean replayAndGenerateGlobalStateMgrImage(long logVersion) {
assert belongToGlobalStateMgr;
long replayedJournalId = -1;
// generate new image file
LOG.info("begin to generate new image: image.{}", logVersion);
globalStateMgr = GlobalStateMgr.getCurrentState();
globalStateMgr.setJournal(journal);
try {
globalStateMgr.loadImage(imageDir);
globalStateMgr.replayJournal(logVersion);
globalStateMgr.clearExpiredJobs();
globalStateMgr.saveImage();
replayedJournalId = globalStateMgr.getReplayedJournalId();
if (MetricRepo.hasInit) {
MetricRepo.COUNTER_IMAGE_WRITE.increase(1L);
}
GlobalStateMgr.getServingState().setImageJournalId(logVersion);
LOG.info("checkpoint finished save image.{}", replayedJournalId);
return true;
} catch (Exception e) {
LOG.error("Exception when generate new image file", e);
return false;
} finally {
// destroy checkpoint globalStateMgr, reclaim memory
globalStateMgr = null;
GlobalStateMgr.destroyCheckpoint();
}
}
因為個人主觀覺得Checkpoint失敗的可能性比較大，因此開始在fe的warn日志中執(zhí)行下列語句檢索相關(guān)的異常，
cat fe.warn.log | grep 'Exception when generate new image file'
可以看到在fe日志中出現(xiàn)了大量的Checkpoint操作失敗的相關(guān)日志信息。
由以上日志再配合源碼，可以發(fā)現(xiàn)其觸發(fā)了Checkpoint操作，但是Checkpoint過程中出現(xiàn)了異常，導(dǎo)致CheckPoint過程失敗，也就造成了整個image一直沒有更新。繼而繼續(xù)查詢?nèi)罩?，找失敗的原因，在該日志信息的后面可以看到其報錯信息，其信息如下：
基于上面的操作，已經(jīng)得到了出現(xiàn)Checkpoint失敗的原因，也就是得到的journal id和期望值不一致。
記錄一個Linux的查詢文件命令
由于StarRocks在恢復(fù)期間，整個日志文件非常的大，而且刷新很快，通過tail more等看起來非常耗時，因此百度之后發(fā)現(xiàn)如下兩個命令配合，可以非常的方便定位異常點：
cat -n 文件 | grep '異常信息' 這個命令，可以查詢出整個文件中出現(xiàn)異常的行，并且顯示行號。
sed -n '開始行號,讀取行數(shù)p' 文件 這個命令，可以從文件的某一行開始向下讀取多少行。
四、解決過程與原理分析
基于上面找到的Checkpoint失敗的原因，首先在高于3.1.4版本的各個版本的發(fā)布信息中查詢，沒有發(fā)現(xiàn)相關(guān)問題修復(fù)的bugfix記錄。
然后在StarRocks中文論壇中進(jìn)行相關(guān)的檢索，雖然有相關(guān)的問題，但是都不太一致，其中最相近的一個帖子為:
無法生成image文件，fe重啟后元數(shù)據(jù)還原, 其中提到了通過dump操作進(jìn)行恢復(fù)，但是查詢StarRocks相關(guān)的文檔之后，并沒有發(fā)現(xiàn)其中有相關(guān)操作的描述。
然后遇事不決翻源碼，查看最近和Checkpoint相關(guān)的代碼不是是否出現(xiàn)了變更，跟蹤相關(guān)部分的源碼發(fā)現(xiàn)在GlobalStateMgr.java(fe/fe-core/src/main/java/com/starrocks/server/GlobalStateMgr.java)類中的replayJournalInner方法，最近進(jìn)行了一次bugfix，查看這次bugfix的問題。
本次bugfix操作的說明如下:
If metadata_journal_skip_bad_journal_ids is configured, and replay of journal failed on EditLog.loadJournal, the cursor will ignore the next journal by mistake, because the bad log data has been read and cursor is already on the next journal. So the next data should only be ignored when failure happens in cursor.next().
可以看到這個異常和使用過 metadata_journal_skip_bad_journal_ids 這個配置有關(guān)，回想5月16那天是否對StarRocks進(jìn)行過相關(guān)操作。
5月16號那天StarRocks異常崩潰，在重啟恢復(fù)過程中，出現(xiàn)了某一個journal無法加載的錯誤(got interrupt exception or inconsistent exception when replay journal 447554621 wii exit.)，導(dǎo)致一直無法恢復(fù)，當(dāng)時通過查詢StarRocks中文論壇，找到了一篇如下的帖子：3.1.5 存算分離集群FE 宕機(jī)后沒法啟動, 其中提到了配置 metadata_journal_skip_bad_journal_ids 跳過該journal，當(dāng)時采用了這個操作，跳過了那個journal，結(jié)合目前來看，極大可能就是這個配置導(dǎo)致了FE無法進(jìn)行Checkpoint.
在來分析本次bugfix到底干了啥，本次bugfix的源碼變更地方如下：
可以發(fā)現(xiàn)，其就是在獲取和或加載某個journal失敗的時候，調(diào)用了cursor.skipNext(),查看這個具體代表的含義：在其實現(xiàn)類BDBJEJournal.java(fe/fe-core/src/main/java/com/starrocks/journal/bdbje/BDBJEJournal.java)中，其實現(xiàn)如下：
public void skipNext() {
LOG.error("!!! DANGER: CURSOR SKIP {} !!!", nextKey);
nextKey++;
}
再看具體報錯should replay to 539780547 but actual replayed journal id is 539780546的地方源碼，其在
GlobalStateMgr.java(fe/fe-core/src/main/java/com/starrocks/server/GlobalStateMgr.java)中的replayJournal方法中，其實現(xiàn)如下：
public void replayJournal(long toJournalId) throws JournalException {
if (toJournalId <= replayedJournalId.get()) {
LOG.info("skip replay journal because {} <= {}", toJournalId,
replayedJournalId.get());
return;
}
long startJournalId = replayedJournalId.get() + 1;
long replayStartTime = System.currentTimeMillis();
LOG.info("start to replay journal from {} to {}", startJournalId, toJournalId);
JournalCursor cursor = null;
try {
cursor = journal.read(startJournalId, toJournalId);
replayJournalInner(cursor, false);
} catch (InterruptedException | JournalInconsistentException e) {
LOG.warn("got interrupt exception or inconsistent exception when replay
journal {}, will exit, ",replayedJournalId.get() + 1,e);
// TODO exit gracefully
Util.stdoutWithTime(e.getMessage());
System.exit(-1);
} finally {
if (cursor != null) {
cursor.close();
}
}
// verify if all log is replayed
if (toJournalId != replayedJournalId.get()) {
throw new JournalException(String.format(
"should replay to %d but actual replayed journal id is %d",
toJournalId, replayedJournalId.get()));
}
streamLoadMgr.cancelUnDurableTaskAfterRestart();
long replayInterval = System.currentTimeMillis() - replayStartTime;
LOG.info("finish replay from {} to {} in {} msec", startJournalId, toJournalId,
replayInterval);
}
從報錯新增可以看到，其判斷條件是：toJournalId != replayedJournalId.get()， 那么解下來看這兩個值是如何得到的。
在Checkpoint.java中可以看到toJournal來自于 journal.getFinalizedJournalId();通過其實現(xiàn)可以看到， 其取的是當(dāng)前元數(shù)據(jù)中的最后的一個journalId。
public long getFinalizedJournalId() {
List<Long> dbNames = bdbEnvironment.getDatabaseNamesWithPrefix(prefix);
assert (dbNames != null);
StringBuilder msg = new StringBuilder("database names: ");
for (long name : dbNames) {
msg.append(name).append(" ");
}
LOG.info(msg.toString());
if (dbNames.size() < 2) {
return 0;
}
return dbNames.get(dbNames.size() - 1) - 1;
}
接下來再看整個日志的重放過程，replayedJournalId的初始值，就是image文件的后綴（在fe/fe-core/src/main/java/com/starrocks/persist/Storage.java的reload方法中可以看到），然后其在重放的過程中會不斷+1，replayedJournalId更新的邏輯如下：
protected boolean replayJournalInner(JournalCursor cursor, boolean flowControl)
throws JournalException, InterruptedException, JournalInconsistentException {
long startReplayId = replayedJournalId.get();
long startTime = System.currentTimeMillis();
long lineCnt = 0;
while (true) {
JournalEntity entity = null;
boolean readSucc = false;
try {
entity = cursor.next();
// EOF or aggressive retry
if (entity == null) {
break;
}
readSucc = true;
// apply
EditLog.loadJournal(this, entity);
} catch (Throwable e) {
if (canSkipBadReplayedJournal(e)) {
LOG.error("!!! DANGER: SKIP JOURNAL, id: {}, data: {} !!!",
replayedJournalId.incrementAndGet(),
journalEntityToReadableString(entity), e);
if (!readSucc) {
cursor.skipNext();
}
continue;
}
// handled in outer loop
LOG.warn("catch exception when replaying journal, id: {}, data: {},",
replayedJournalId.get() + 1, journalEntityToReadableString(entity), e);
throw e;
}
replayedJournalId.incrementAndGet();
LOG.debug("journal {} replayed.", replayedJournalId);
if (feType != FrontendNodeType.LEADER) {
journalObservable.notifyObservers(replayedJournalId.get());
}
if (MetricRepo.hasInit) {
// Metric repo may not init after this replay thread start
MetricRepo.COUNTER_EDIT_LOG_READ.increase(1L);
}
if (flowControl) {
// cost too much time
long cost = System.currentTimeMillis() - startTime;
if (cost > REPLAYER_MAX_MS_PER_LOOP) {
LOG.warn("replay journal cost too much time: {} replayedJournalId: {}",
cost, replayedJournalId);
break;
}
// consume too much lines
lineCnt += 1;
if (lineCnt > REPLAYER_MAX_LOGS_PER_LOOP) {
LOG.warn("replay too many journals: lineCnt {}, replayedJournalId: {}",
lineCnt, replayedJournalId);
break;
}
}
}
if (replayedJournalId.get() - startReplayId > 0) {
LOG.info("replayed journal from {} - {}", startReplayId, replayedJournalId);
return true;
}
return false;
}
分析以上代碼：其在while循環(huán)中不斷讀取journal，二而且通過replayedJournalId.incrementAndGet()不斷刷新其值。
可以發(fā)現(xiàn)在修改前后的不同點
- 修改前：不管的讀取還是加載節(jié)點異常，其值都加1，而且如果某個失敗，并且在 metadata_journal_skip_bad_journal_ids 配置了可以跳過，那么循環(huán)會繼續(xù)，但是游標(biāo)都會+1.
- 修改后：加了判斷，只有在日志加載中失敗，游標(biāo)才會+1，如果是讀取成功，但是加載失敗并且又被跳過，則其游標(biāo)不會+1.
由此，豁然開朗，因為某個journal在EditLog加載過程中失敗了，并且這個journal又因為被配置在了metadata_journal_skip_bad_journal_ids中，因此這個錯誤被被跳過，但是按照修改之前的代碼，游標(biāo)還是+1，跳過了下一個journal，導(dǎo)致replayedJournal的值少自增了一次，導(dǎo)致其值比正常的小了1。
由此，我們就確定了這哥bugfix確實解決了這個問題，因此我們的解決方案就是升級版本。
五、結(jié)果
查看該bugfix合并進(jìn)入3.1相關(guān)分支的時間，發(fā)現(xiàn)其為2023.11.9，目前出問題的版本為3.1.4，其發(fā)布時間為2023.11.2，確定這個bugfix沒有被合并進(jìn)入， 于是選擇進(jìn)行升級，將其升級到了3.2.13.
經(jīng)過5個小時左右的升級恢復(fù)，成功生成了新的image文件，BDB文件也從原先的8000多個講到了80多個。
六、參考
整個過程中，收集到的一些相關(guān)參考資料
- metadata_journal_skip_bad_journal_ids：https://forum.mirrorship.cn/t/topic/10178
- 無法生成image文件，fe重啟后元數(shù)據(jù)還原： https://forum.mirrorship.cn/t/topic/7774
- bugfix：https://github.com/StarRocks/starrocks/pull/33839
- 元數(shù)據(jù)dump相關(guān)(來自Doris，StarRocks未查詢到):https://cdnd.selectdb.com/zh-CN/docs/admin-manual/maint-monitor/metadata-operation?_highlight=bdb#%E6%9F%A5%E7%9C%8B-bdbje-%E4%B8%AD%E7%9A%84%E6%95%B0%E6%8D%AE
- 元數(shù)據(jù)管理源碼分析：https://xie.infoq.cn/article/6f2f9f56916f0eb2fdb6b001a
