也可以看我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ù)。