Flink Checkpoint超時問題常見排查思路

一護發表於2019-01-10

本文大致理一下checkpoint出現超時問題的排查思路：（本文基於flink-1.4.2）

超時判斷邏輯

jobmanager定時trigger checkpoint，給source處傳送trigger訊號，同時會啟動一個非同步執行緒，在checkpoint timeout時長之後停止本輪 checkpoint，cancel動作執行之後本輪的checkpoint就為超時，如果在超時之前收到了最後一個sink運算元的ack訊號，那麼checkpoint就是成功的。

那麼超時的原因會是什麼呢？時間要麼花費在barrier對齊，要麼花費在非同步狀態遍歷和寫hdfs 第二種型別會很好看，因為狀態很大的時候就會出現這 個現象，下面分析第一類出現的原因

Barrier處理流程

StreamTask收集到相應的inputChannel的barrier，收集齊之後就將barrier下發，並開始自己task的checkpoint邏輯，如果上下游是rescale或者 forward的形式，下游只需要等待1個併發的barrier，因為是point-to-point的，如果是hash或者rebalance，下游的每一個task開始checkpoint的 前提就是要收集齊上游所有併發的barrier。

Barrier傳送流程

RecordWriter#broadcastEvent

這個方法是專門用於barrier的下發，首先會將serializer中還沒下發的部分已經寫入資料的buffer下發防止barrier越過資料下發的行為，保證一致性， 同時會將barrier包裝成buffer物件，此處不申請堆外記憶體，直接將堆內記憶體包裝成一個buffer下發。

PipelinedSubpartition#add

將要傳送給下游的資料add到subpartition中，同時通知監聽的subpartitionView，notifybufferAvailable事件，這裡notify操作會區分 本地和遠端兩種channel不同處理，我們看到的都是遠端消費的延遲問題，本地其實就立馬執行下游的barrier收集動作了，遠端的需要有網路傳輸過程。

server netty handler

LengthFieldBasedFrameDecoder => messageDecode => PartitionRequestServerHandler => PartitionRequestQueue => messageEncoder notifybufferAvailable事件最終會觸發PartitionRequestQueue去將資料writeAndFlush到netty client中，在flush之前會判斷channel 是否可寫，在flush成功後，會執行相應的listener -> barrier的處理邏輯，這裡可以hack程式碼使其在傳送barrier的時候回撥列印barrier傳送成功， 使我們確認barrier已經從上游傳送成功。

barrie接收流程

LengthFieldBasedFrameDecoder => messageDecode => PartitionRequestClientHandler => messageEncoder 首先讀入訊息時候會判斷是否有堆積的stagedMessages，如果有則不處理，add到堆積訊息中，如果沒有將資料從netty buffer中拷貝至localbuffer中 ，這時候需要requestBuffer，這個方法並不block消費流程，但是如果request不到buffer那麼會將資料丟入到stagedMessages，同時監聽bufferpool， 等到buffer有recyle的時候就會開始buffer的轉化，並且這個是時候會將channel的auto read標誌置為false，因此這個通道就不再讀入資料，barrier 也是無法讀入的，並且每個taskmanager共享一個channel，因此taskmanager上只要阻塞了就會影響這個taskmanager上的消費。

小結

從以上可以看出，其實barrier下游無法對齊的主要原因還是在於下游消費能力不足，會導致buffer堆積一段時間，但這時並不足以造成上游反壓，因為反壓 需要下游channel持續無法寫入，導致tcp阻塞，導致上游的outputbuffer佔滿才會引起反壓。

一般的排查方式

檢視ui上的失敗checkpoint的detail，可以看到失敗的是Pending -> EventEmit xxx這個運算元的10個subtask。

checkpoint

一般由於barrier對齊原因沒開始的subtask會是開始時間都是n/a，因為在彙報CheckpointStats的時候根本還沒開始checkpoint，注意這裡的11，12 並不是subtaskIndex，這裡千萬不要被誤導了去檢視這個subtask的問題。

checkpoint

接著去jobmanager上檢視這個checkpoint的一些延遲資訊

2018-11-29 18:43:04,624 INFO  org.apache.flink.runtime.checkpoint.CheckpointCoordinator     - Checkpoint 224 expired before completing.
2018-11-29 18:43:26,763 WARN  org.apache.flink.runtime.checkpoint.CheckpointCoordinator     - Received late message for now expired checkpoint attempt 224 from f2862289958b430bc3dc20f39794ca2c of job 7c7769847d333438dd9ce845d5a2d980.
2018-11-29 18:43:26,766 WARN  org.apache.flink.runtime.checkpoint.CheckpointCoordinator     - Received late message for now expired checkpoint attempt 224 from 8f569166274106f22e49ed2ce919c930 of job 7c7769847d333438dd9ce845d5a2d980.
2018-11-29 18:43:26,770 WARN  org.apache.flink.runtime.checkpoint.CheckpointCoordinator     - Received late message for now expired checkpoint attempt 224 from a29e34c210b39104004af7f067c1a5d0 of job 7c7769847d333438dd9ce845d5a2d980.
2018-11-29 18:43:26,771 WARN  org.apache.flink.runtime.checkpoint.CheckpointCoordinator     - Received late message for now expired checkpoint attempt 224 from 7d4914521fd53fca56a4050d6f191ae9 of job 7c7769847d333438dd9ce845d5a2d980.
2018-11-29 18:43:26,771 WARN  org.apache.flink.runtime.checkpoint.CheckpointCoordinator     - Received late message for now expired checkpoint attempt 224 from 618c78d0008d0d525728ff9824339229 of job 7c7769847d333438dd9ce845d5a2d980.
2018-11-29 18:43:26,773 WARN  org.apache.flink.runtime.checkpoint.CheckpointCoordinator     - Received late message for now expired checkpoint attempt 224 from c8ba24a328234dc7f2f271db4a8eb1e3 of job 7c7769847d333438dd9ce845d5a2d980.
2018-11-29 18:43:26,777 WARN  org.apache.flink.runtime.checkpoint.CheckpointCoordinator     - Received late message for now expired checkpoint attempt 224 from 72af6c722fcc085dc8f7c46e9124d82e of job 7c7769847d333438dd9ce845d5a2d980.
2018-11-29 18:43:26,777 WARN  org.apache.flink.runtime.checkpoint.CheckpointCoordinator     - Received late message for now expired checkpoint attempt 224 from f824cb6920b04d19e05278ee362ec675 of job 7c7769847d333438dd9ce845d5a2d980.
2018-11-29 18:43:26,780 WARN  org.apache.flink.runtime.checkpoint.CheckpointCoordinator     - Received late message for now expired checkpoint attempt 224 from af6d867d2f12be23c7b23a938aba7c5e of job 7c7769847d333438dd9ce845d5a2d980.
2018-11-29 18:43:27,265 WARN  org.apache.flink.runtime.checkpoint.CheckpointCoordinator     - Received late message for now expired checkpoint attempt 224 from cee0205fe9a85e3e89e023a1166ed1e6 of job 7c7769847d333438dd9ce845d5a2d980.
2018-11-29 18:43:44,624 INFO  org.apache.flink.runtime.checkpoint.CheckpointCoordinator     - Triggering checkpoint 225 @ 1543488224622
複製程式碼

可以根據這些失敗的task的id去查詢這些任務落在哪一個taskmanager上，經過排查發現，是同一臺機器，通過ui看到該機器流入的資料明顯比別的流入量大 因此是因為資料傾斜導致了這個問題，追根溯源還是下游消費能力不足的問題

指標

可以反映一個運算元的指標有幾個

  • inPoolUsage
  • OutPoolUsage
  • OutputQueueLength
  • inputQueueLength

首先前3個值都是未加鎖獲得的非準確資料，為了資料消費本身的效能，參考意義不大。而inputQueueLength可以加以參考，為什麼這個加鎖了，可能 是社群遺漏了。。這個值最大應該是（分割槽如果是hash，其他分割槽方式會更小一點）上游併發 * 2 + 8 + 上游併發，如果到達這個值左右，此時傳送barrier 到下游會無法反序列化並進行正確的checkpoint操作，至於為什麼最後一個上游併發單獨拎開，是因為這個含義表示的barrier數量，barrier的數量也會算 在inputQueueLength內。

在flink1.5之後的@zhijiangW網路棧優化後的版本中據說checkpointBarrier是可以越過資料優先傳送，需要確認這種情況下如何保障處理的exactly once語義呢？

相關文章