也可以看我CSDN的博客
https://blog.csdn.net/u013332124/article/details/88758290

本周三公司的yarn集群出現(xiàn)故障，導致兩臺ResourceManger頻繁易主，并且許多提交到集群的任務狀態(tài)為NEW_SAVING，無法執(zhí)行。這里對此次的故障排查進行一個總結(jié)。

一、故障現(xiàn)象

1. 兩個節(jié)點的ResourceManger頻繁在active和standby角色中切換。不斷有active易主的告警發(fā)出
2. 許多任務的狀態(tài)沒能成功更新，導致一些任務狀態(tài)卡在NEW_SAVING無法進入調(diào)度（還有許多資源空閑）

看了下ResourceManger的日志，發(fā)現(xiàn)大量以下錯誤:

org.apache.zookeeper.KeeperException$ConnectionLossException: KeeperErrorCode = ConnectionLoss

在這里插入圖片描述

在這里插入圖片描述

從日志可以看出是在操作zk時出現(xiàn)了錯誤，并且會進行重試。RM在重試1000次后才會放棄嘗試。并且從日志可以看出，這是在更新任務appattempt_1535616282827_1432747_000002的狀態(tài)時發(fā)生的異常。

緊接著后面還發(fā)現(xiàn)另外一條日志，表示此時RM的狀態(tài)進入了standby:

2019-03-20 14:37:48,914 INFO org.apache.hadoop.yarn.server.resourcemanager.ResourceManager: Transitioning to standby state

RM進入standby狀態(tài)前會將對應的ZK節(jié)點/yarn/ActiveStandbyElectorLock刪除，然后再轉(zhuǎn)到standby狀態(tài)。這時兩臺RM同時開始競爭嘗試新建/yarn/ActiveStandbyElectorLock節(jié)點，誰競爭到誰就是active。

成為active的節(jié)點又收到appattempt_1535616282827_1432747_000002的狀態(tài)更新，就嘗試更新zk節(jié)點的數(shù)據(jù)，然后又發(fā)生上面的錯誤，重試1000次后轉(zhuǎn)為standby。如此一直重復下去，直到人為介入kill了該任務，集群才恢復正常。

因為是zk操作的問題，所以看了下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這個任務狀態(tài)會更新失敗，其他任務的狀態(tài)都可以正常更新，有一些任務會因為zk連接被關閉而更新失敗，這個后面解釋原因。

二、問題分析

RM的HA機制分析

之前一直以為RM只有在和zk失聯(lián)，/yarn/ActiveStandbyElectorLock節(jié)點斷開后才會進行易主。但是這次的異常卻顛覆了我的認知。于是去跟了下yarn的源碼。發(fā)現(xiàn)還有一種情況可能導致RM從active狀態(tài)切換到standby狀態(tài)。

RM在進行任務狀態(tài)更新時，會進行對應的zk操作，也就是將任務的相關信息存儲到zk。如果這個失敗，RM會進行重試，這個重試的次數(shù)可以通過yarn.resourcemanager.zk-num-retries配置，默認是1000次。當對應的zk操作失敗重試達到1000次，RM就會將狀態(tài)切換到standby。

具體可能導致active切換成standby的操作有以下這些：

1. storeApplicationStateInternal
2. updateApplicationStateInternal
3. removeApplicationStateInternal
4. storeApplicationAttemptStateInternal
5. updateApplicationAttemptStateInternal
6. storeRMDelegationTokenState
7. removeRMDelegationTokenState
8. updateRMDelegationTokenState
9. storeRMDTMasterKeyState
10. removeRMDTMasterKeyState
11. storeOrUpdateAMRMTokenSecretManagerState

所以我們上面的故障很明顯就是在某個任務的updateApplicationAttemptStateInternal操作出現(xiàn)異常后，才導致active在兩個RM節(jié)點間不斷切換的。

如果配置了多個RM，客戶端根據(jù)yarn-site.xml的配置會采用round-robin的方式逐個去連接RM，直到找到active 節(jié)點位置。所以即使active節(jié)點切換，在運行中的客戶端也能通過這種方式重新找到新的Active RM進行連接。

ZK問題分析

上面的故障其實歸根結(jié)底還是zk的問題。zk的這條日志Exception causing close of session 0x16324e8243d0003 due to java.io.IOException: Len error 2186401也很明確的表明是由于客戶端發(fā)來的請求包太大，zk主動關閉了連接。

上網(wǎng)搜了下zk的Len error的問題，發(fā)現(xiàn)也有一些人碰到過。甚至找到兩個相關的issue，一個是yarn的，一個是zookeeper的:

https://issues.apache.org/jira/browse/YARN-3469

https://issues.apache.org/jira/browse/ZOOKEEPER-706

其中zk的issue是說如果一個請求要注冊的watcher太多，會導致Len error的問題。因此這個issue的patch是將這些watcher分成多個請求發(fā)送，這樣就不會導致請求過大的問題了。剛好修復版本是3.4.7，而我們集群用的zk版本是3.4.6。

yarn的issue是說之前的版本設置了過多無用的watcher，導致某個請求太大，出現(xiàn)Len error的問題。因此yarn這邊做的修復是不在注冊無用的watcher。修復版本是2.6.0，我們集群用的版本是2.7.4，因此我們集群應該不會有這個問題。

因為排查時已經(jīng)無法找到那個請求包的具體內(nèi)容，這兩個issue看上去又很有說服力。雖然yarn已經(jīng)修復了注冊過多無用watcher的，但是可能還有一些地方還有類似的問題呢。

本來以為問題大概就是這樣了，我們已經(jīng)準備升級zk版本了。突然又想到失敗的zk操作是updateApplicationAttemptStateInternal，它底層的zk操作是setData，而setData是不會注冊任何watcher的。因此這個問題和watcher沒有任何關系。

后面繼續(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。也就是我們遇到的問題。就是要更新的任務信息過大導致的，和watcher沒有關系。

這issue并沒有修復的版本，看了下它的patch，就是加了一個配置，用來指定jute.maxbuffer，也就是通過調(diào)大zk的閥值來避免出現(xiàn)該問題。

部分任務狀態(tài)更新失敗問題分析

從日志看，只有appattempt_1535616282827_1432747_000002這個任務因為更新內(nèi)容過大導致zk操作失敗。但是故障時看到的現(xiàn)象確實許多任務狀態(tài)都卡在NEW_SAVING無法更新。這是為什么呢？

通過分析日志，可以很容易得出結(jié)論。RM在更新appattempt_1535616282827_1432747_000002狀態(tài)失敗時，zk服務端主動斷掉了連接，RM在下次重試時就會再次嘗試建立連接。

因為任務狀態(tài)更新用的zk連接可能是同一個，如果要更新時剛好連接被關閉了，任務肯定無法成功更新。因此才會有部分任務狀態(tài)可以更新，部分任務狀態(tài)無法更新的現(xiàn)象。

在RM的日志中我們也可以看到許多下面的Broken pipe異常：

在這里插入圖片描述

三、解決和優(yōu)化方案

1. 調(diào)大 jute.maxbuffer 參數(shù)

通過調(diào)大jute.maxbuffer來讓zk可以接受更大的請求包而不會拋出IOException。這個參數(shù)的默認值是1M。

注意，這個不是在zk的配置文件中設置。而是作為java參數(shù)在啟動zk時設置，也就是-Djute.maxbuffer=xxxx的方式。

另外，根據(jù)zk的文檔，這個參數(shù)在所有的客戶端和zk服務端都要設置，否則會有更多的問題產(chǎn)生。也就是說，我們需要在yarn這邊也設置這個參數(shù)。

這種方式有點治標不治本，因為我們無法知道任務信息最大可能到多少。設置過大的值也不是個好主意。最重要的是這個方案要同時對yarn和zk進行重啟，風險略高。

2. 修改yarn的源碼

雖然知道了問題的原因所在，但是我們還不知道為什么那個任務會產(chǎn)生那么大的任務信息。所以我們對zk的端口進行抓包查看正常的任務信息的請求都有多大：

在這里插入圖片描述

通過抓包的結(jié)果，我們發(fā)現(xiàn)正常任務包的大小其實都只有幾K，最高不會超過5K。所以我們打算修改yarn的源碼過濾掉那些大小超過1M的任務更新請求，同時把這些大于1M的請求內(nèi)容打印出來。

這樣做一方面是為了避免后面因為某個任務的更新失敗又導致集群出現(xiàn)問題，另一方面也可以觀察到為什么有的任務會產(chǎn)生那么大的信息。

附上更新的代碼,ZKRMStateStore#updateApplicationAttemptStateInternal()

    byte[] attemptStateData = attemptStateDataPB.getProto().toByteArray();
 //測試環(huán)境可以加上下面這個日志，實時觀察各個任務信息的大小
LOG.info(String.format("attempId:%s,len:%s",attemptStateDataPB.getAttemptId(),attemptStateData.length));
    //如果任務信息超過了950K，就打出error日志，輸出任務信息，同時直接返回，不再往zk發(fā)送請求
    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ā)送請求更新任務信息
    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. 快速讓集群恢復穩(wěn)定的方法

如果集群又發(fā)生了類似的問題，可以找到任務的ApplicationMaster所在的Container，然后上目標服務器將對應的Container進程kill掉，后面RM就不會再更新該任務的信息，而是將任務直接轉(zhuǎn)為Kill狀態(tài)。

四、總結(jié)

此次故障大概持續(xù)了2個半小時才恢復，還是剛好業(yè)務同學手動kill了那個任務的container進程，最終才沒有一直切換下去。

因為之前對yarn只有原理上的認知，并沒有看過yarn的代碼，對yarn狀態(tài)機的相關知識也了解不多。所以在故障發(fā)生時有點手足無措，不知道從何下手排查。

此刻回想起來真的很僥幸，因為這個故障不是重啟一下RM就能恢復的。如果業(yè)務同學沒有剛好kill那個container進程，可能我們要一直排查到分析出問題的根本原因為止，至少要多半天的時間。

后面還是要多看看集群各個組件的源碼，深入了解他們的架構(gòu)，爭取出現(xiàn)問題時能更快的定位到問題并修復。