也可以看我CSDN的博客
https://blog.csdn.net/u013332124/article/details/88758290
本周三公司的yarn集群出現(xiàn)故障尽纽，導(dǎo)致兩臺(tái)ResourceManger頻繁易主幌缝，并且許多提交到集群的任務(wù)狀態(tài)為NEW_SAVING衰絮，無法執(zhí)行缴淋。這里對(duì)此次的故障排查進(jìn)行一個(gè)總結(jié)。
一敦腔、故障現(xiàn)象
- 兩個(gè)節(jié)點(diǎn)的ResourceManger頻繁在active和standby角色中切換缆八。不斷有active易主的告警發(fā)出
- 許多任務(wù)的狀態(tài)沒能成功更新，導(dǎo)致一些任務(wù)狀態(tài)卡在NEW_SAVING無法進(jìn)入調(diào)度（還有許多資源空閑）
看了下ResourceManger的日志蛔琅，發(fā)現(xiàn)大量以下錯(cuò)誤:
org.apache.zookeeper.KeeperException$ConnectionLossException: KeeperErrorCode = ConnectionLoss
從日志可以看出是在操作zk時(shí)出現(xiàn)了錯(cuò)誤胎许，并且會(huì)進(jìn)行重試。RM在重試1000次后才會(huì)放棄嘗試。并且從日志可以看出辜窑，這是在更新任務(wù)appattempt_1535616282827_1432747_000002的狀態(tài)時(shí)發(fā)生的異常钩述。
緊接著后面還發(fā)現(xiàn)另外一條日志，表示此時(shí)RM的狀態(tài)進(jìn)入了standby:
2019-03-20 14:37:48,914 INFO org.apache.hadoop.yarn.server.resourcemanager.ResourceManager: Transitioning to standby state
RM進(jìn)入standby狀態(tài)前會(huì)將對(duì)應(yīng)的ZK節(jié)點(diǎn)/yarn/ActiveStandbyElectorLock刪除穆碎，然后再轉(zhuǎn)到standby狀態(tài)牙勘。這時(shí)兩臺(tái)RM同時(shí)開始競(jìng)爭嘗試新建/yarn/ActiveStandbyElectorLock節(jié)點(diǎn)，誰競(jìng)爭到誰就是active所禀。
成為active的節(jié)點(diǎn)又收到appattempt_1535616282827_1432747_000002的狀態(tài)更新方面，就嘗試更新zk節(jié)點(diǎn)的數(shù)據(jù)，然后又發(fā)生上面的錯(cuò)誤色徘，重試1000次后轉(zhuǎn)為standby葡幸。如此一直重復(fù)下去，直到人為介入kill了該任務(wù)贺氓，集群才恢復(fù)正常蔚叨。
因?yàn)槭莦k操作的問題，所以看了下zk的日志辙培，也發(fā)現(xiàn)了異常：
2019-03-20 14:37:40,141 [myid:1] - WARN [NIOServerCxn.Factory:0.0.0.0/0.0.0.0:2181:NIOServerCnxn@362] - Exception causing close of session 0x16324e8243d0003 due to java.io.IOException: Len error 2186401
2019-03-20 14:37:40,142 [myid:1] - INFO [NIOServerCxn.Factory:0.0.0.0/0.0.0.0:2181:NIOServerCnxn@1007] - Closed socket connection for client /192.168.142.10:23412 which had sessionid 0x16324e8243d0003
從日志上看蔑水，只有appattempt_1535616282827_1432747_000002這個(gè)任務(wù)狀態(tài)會(huì)更新失敗，其他任務(wù)的狀態(tài)都可以正常更新扬蕊，有一些任務(wù)會(huì)因?yàn)閦k連接被關(guān)閉而更新失敗搀别，這個(gè)后面解釋原因。
二尾抑、問題分析
RM的HA機(jī)制分析
之前一直以為RM只有在和zk失聯(lián)歇父，/yarn/ActiveStandbyElectorLock節(jié)點(diǎn)斷開后才會(huì)進(jìn)行易主。但是這次的異常卻顛覆了我的認(rèn)知再愈。于是去跟了下yarn的源碼榜苫。發(fā)現(xiàn)還有一種情況可能導(dǎo)致RM從active狀態(tài)切換到standby狀態(tài)。
RM在進(jìn)行任務(wù)狀態(tài)更新時(shí)翎冲，會(huì)進(jìn)行對(duì)應(yīng)的zk操作垂睬，也就是將任務(wù)的相關(guān)信息存儲(chǔ)到zk。如果這個(gè)失敗抗悍，RM會(huì)進(jìn)行重試驹饺，這個(gè)重試的次數(shù)可以通過yarn.resourcemanager.zk-num-retries配置，默認(rèn)是1000次缴渊。當(dāng)對(duì)應(yīng)的zk操作失敗重試達(dá)到1000次赏壹，RM就會(huì)將狀態(tài)切換到standby。
具體可能導(dǎo)致active切換成standby的操作有以下這些：
- storeApplicationStateInternal
- updateApplicationStateInternal
- removeApplicationStateInternal
- storeApplicationAttemptStateInternal
- updateApplicationAttemptStateInternal
- storeRMDelegationTokenState
- removeRMDelegationTokenState
- updateRMDelegationTokenState
- storeRMDTMasterKeyState
- removeRMDTMasterKeyState
- storeOrUpdateAMRMTokenSecretManagerState
所以我們上面的故障很明顯就是在某個(gè)任務(wù)的updateApplicationAttemptStateInternal操作出現(xiàn)異常后衔沼，才導(dǎo)致active在兩個(gè)RM節(jié)點(diǎn)間不斷切換的蝌借。
如果配置了多個(gè)RM田柔，客戶端根據(jù)yarn-site.xml的配置會(huì)采用round-robin的方式逐個(gè)去連接RM，直到找到active 節(jié)點(diǎn)位置骨望。所以即使active節(jié)點(diǎn)切換硬爆，在運(yùn)行中的客戶端也能通過這種方式重新找到新的Active RM進(jìn)行連接。
ZK問題分析
上面的故障其實(shí)歸根結(jié)底還是zk的問題擎鸠。zk的這條日志Exception causing close of session 0x16324e8243d0003 due to java.io.IOException: Len error 2186401也很明確的表明是由于客戶端發(fā)來的請(qǐng)求包太大缀磕，zk主動(dòng)關(guān)閉了連接。
上網(wǎng)搜了下zk的Len error的問題劣光，發(fā)現(xiàn)也有一些人碰到過袜蚕。甚至找到兩個(gè)相關(guān)的issue，一個(gè)是yarn的绢涡，一個(gè)是zookeeper的:
https://issues.apache.org/jira/browse/YARN-3469
https://issues.apache.org/jira/browse/ZOOKEEPER-706
其中zk的issue是說如果一個(gè)請(qǐng)求要注冊(cè)的watcher太多牲剃，會(huì)導(dǎo)致Len error的問題。因此這個(gè)issue的patch是將這些watcher分成多個(gè)請(qǐng)求發(fā)送雄可，這樣就不會(huì)導(dǎo)致請(qǐng)求過大的問題了凿傅。剛好修復(fù)版本是3.4.7，而我們集群用的zk版本是3.4.6数苫。
yarn的issue是說之前的版本設(shè)置了過多無用的watcher聪舒，導(dǎo)致某個(gè)請(qǐng)求太大，出現(xiàn)Len error的問題虐急。因此yarn這邊做的修復(fù)是不在注冊(cè)無用的watcher箱残。修復(fù)版本是2.6.0，我們集群用的版本是2.7.4止吁，因此我們集群應(yīng)該不會(huì)有這個(gè)問題被辑。
因?yàn)榕挪闀r(shí)已經(jīng)無法找到那個(gè)請(qǐng)求包的具體內(nèi)容，這兩個(gè)issue看上去又很有說服力敬惦。雖然yarn已經(jīng)修復(fù)了注冊(cè)過多無用watcher的盼理，但是可能還有一些地方還有類似的問題呢。
本來以為問題大概就是這樣了仁热，我們已經(jīng)準(zhǔn)備升級(jí)zk版本了榜揖。突然又想到失敗的zk操作是updateApplicationAttemptStateInternal勾哩，它底層的zk操作是setData抗蠢，而setData是不會(huì)注冊(cè)任何watcher的。因此這個(gè)問題和watcher沒有任何關(guān)系思劳。
后面繼續(xù)排查迅矛，發(fā)現(xiàn)下面這篇博客：
https://www.jishuwen.com/d/2BBc/zh-hk#tuit
和我們的故障現(xiàn)象很像，于是追到了博客提到的yarn的issue:
https://issues.apache.org/jira/browse/YARN-2368
ResourceManager failed when ZKRMStateStore tries to update znode data larger than 1MB潜叛。也就是我們遇到的問題秽褒。就是要更新的任務(wù)信息過大導(dǎo)致的壶硅，和watcher沒有關(guān)系。
這issue并沒有修復(fù)的版本销斟，看了下它的patch庐椒，就是加了一個(gè)配置，用來指定jute.maxbuffer蚂踊，也就是通過調(diào)大zk的閥值來避免出現(xiàn)該問題约谈。
部分任務(wù)狀態(tài)更新失敗問題分析
從日志看，只有appattempt_1535616282827_1432747_000002這個(gè)任務(wù)因?yàn)楦聝?nèi)容過大導(dǎo)致zk操作失敗犁钟。但是故障時(shí)看到的現(xiàn)象確實(shí)許多任務(wù)狀態(tài)都卡在NEW_SAVING無法更新棱诱。這是為什么呢？
通過分析日志涝动，可以很容易得出結(jié)論迈勋。RM在更新appattempt_1535616282827_1432747_000002狀態(tài)失敗時(shí)，zk服務(wù)端主動(dòng)斷掉了連接醋粟，RM在下次重試時(shí)就會(huì)再次嘗試建立連接靡菇。
因?yàn)槿蝿?wù)狀態(tài)更新用的zk連接可能是同一個(gè)，如果要更新時(shí)剛好連接被關(guān)閉了米愿，任務(wù)肯定無法成功更新镰官。因此才會(huì)有部分任務(wù)狀態(tài)可以更新，部分任務(wù)狀態(tài)無法更新的現(xiàn)象吗货。
在RM的日志中我們也可以看到許多下面的Broken pipe異常：
三泳唠、解決和優(yōu)化方案
1. 調(diào)大 jute.maxbuffer 參數(shù)
通過調(diào)大jute.maxbuffer來讓zk可以接受更大的請(qǐng)求包而不會(huì)拋出IOException。這個(gè)參數(shù)的默認(rèn)值是1M宙搬。
注意笨腥，這個(gè)不是在zk的配置文件中設(shè)置。而是作為java參數(shù)在啟動(dòng)zk時(shí)設(shè)置勇垛，也就是-Djute.maxbuffer=xxxx的方式脖母。
另外，根據(jù)zk的文檔闲孤，這個(gè)參數(shù)在所有的客戶端和zk服務(wù)端都要設(shè)置谆级，否則會(huì)有更多的問題產(chǎn)生。也就是說讼积，我們需要在yarn這邊也設(shè)置這個(gè)參數(shù)肥照。
這種方式有點(diǎn)治標(biāo)不治本，因?yàn)槲覀儫o法知道任務(wù)信息最大可能到多少勤众。設(shè)置過大的值也不是個(gè)好主意舆绎。最重要的是這個(gè)方案要同時(shí)對(duì)yarn和zk進(jìn)行重啟，風(fēng)險(xiǎn)略高们颜。
2. 修改yarn的源碼
雖然知道了問題的原因所在吕朵，但是我們還不知道為什么那個(gè)任務(wù)會(huì)產(chǎn)生那么大的任務(wù)信息猎醇。所以我們對(duì)zk的端口進(jìn)行抓包查看正常的任務(wù)信息的請(qǐng)求都有多大：
通過抓包的結(jié)果，我們發(fā)現(xiàn)正常任務(wù)包的大小其實(shí)都只有幾K努溃，最高不會(huì)超過5K硫嘶。所以我們打算修改yarn的源碼過濾掉那些大小超過1M的任務(wù)更新請(qǐng)求，同時(shí)把這些大于1M的請(qǐng)求內(nèi)容打印出來梧税。
這樣做一方面是為了避免后面因?yàn)槟硞€(gè)任務(wù)的更新失敗又導(dǎo)致集群出現(xiàn)問題音半，另一方面也可以觀察到為什么有的任務(wù)會(huì)產(chǎn)生那么大的信息。
附上更新的代碼,ZKRMStateStore#updateApplicationAttemptStateInternal()
byte[] attemptStateData = attemptStateDataPB.getProto().toByteArray();
//測(cè)試環(huán)境可以加上下面這個(gè)日志贡蓖，實(shí)時(shí)觀察各個(gè)任務(wù)信息的大小
LOG.info(String.format("attempId:%s,len:%s",attemptStateDataPB.getAttemptId(),attemptStateData.length));
//如果任務(wù)信息超過了950K曹鸠，就打出error日志，輸出任務(wù)信息斥铺，同時(shí)直接返回彻桃，不再往zk發(fā)送請(qǐng)求
if(attemptStateData.length > 972800){
LOG.error(String.format("attemptStateData len larger than 1M.len:%s,nodeUpdatePath:%s,data:%s,attemptId:%s,Diagnostics:%s,traceUrl:%s,container%s",
attemptStateData.length,nodeUpdatePath,String.valueOf(attemptStateData),attemptStateDataPB.getAttemptId(),attemptStateDataPB.getDiagnostics(),
attemptStateDataPB.getFinalTrackingUrl(),attemptStateDataPB.getMasterContainer()));
return;
}
//往zk發(fā)送請(qǐng)求更新任務(wù)信息
if (existsWithRetries(nodeUpdatePath, false) != null) {
setDataWithRetries(nodeUpdatePath, attemptStateData, -1);
} else {
createWithRetries(nodeUpdatePath, attemptStateData, zkAcl,
CreateMode.PERSISTENT);
LOG.debug(appAttemptId + " znode didn't exist. Created a new znode to"
+ " update the application attempt state.");
}
3. 快速讓集群恢復(fù)穩(wěn)定的方法
如果集群又發(fā)生了類似的問題，可以找到任務(wù)的ApplicationMaster所在的Container晾蜘，然后上目標(biāo)服務(wù)器將對(duì)應(yīng)的Container進(jìn)程kill掉邻眷，后面RM就不會(huì)再更新該任務(wù)的信息，而是將任務(wù)直接轉(zhuǎn)為Kill狀態(tài)剔交。
四肆饶、總結(jié)
此次故障大概持續(xù)了2個(gè)半小時(shí)才恢復(fù)，還是剛好業(yè)務(wù)同學(xué)手動(dòng)kill了那個(gè)任務(wù)的container進(jìn)程岖常，最終才沒有一直切換下去驯镊。
因?yàn)橹皩?duì)yarn只有原理上的認(rèn)知，并沒有看過yarn的代碼竭鞍，對(duì)yarn狀態(tài)機(jī)的相關(guān)知識(shí)也了解不多板惑。所以在故障發(fā)生時(shí)有點(diǎn)手足無措，不知道從何下手排查偎快。
此刻回想起來真的很僥幸冯乘，因?yàn)檫@個(gè)故障不是重啟一下RM就能恢復(fù)的。如果業(yè)務(wù)同學(xué)沒有剛好kill那個(gè)container進(jìn)程晒夹，可能我們要一直排查到分析出問題的根本原因?yàn)橹柜陕辽僖喟胩斓臅r(shí)間。
后面還是要多看看集群各個(gè)組件的源碼丐怯，深入了解他們的架構(gòu)喷好，爭取出現(xiàn)問題時(shí)能更快的定位到問題并修復(fù)。
