記一次k8s pod頻繁重啟的優化之旅

踩刀詩人發表於2021-09-24

關鍵詞:k8s、jvm、高可用

 

1.背景

最近有運維反饋某個微服務頻繁重啟,客戶映像特別不好,需要我們儘快看一下。

 

聽他說完我立馬到監控平臺去看這個服務的執行情況,確實重啟了很多次。對於技術人員來說,這既是壓力也是動力,大多數時候我們都是沉浸在單調的業務開發中,對自我的提升有限,久而久之可能會陷入一種舒適區,遇到這種救火案例一時間會有點無所適從,但是沒關係,畢竟......

 

“我只是收了火,但沒有熄爐”,借用電影中的一句話表達一下此時的心情。

 

2.初看日誌

我當即就看這個服務的執行日誌,裡面有大量的oom異常,如下:

org.springframework.web.util.NestedServletException: Handler dispatch failed; 
nested exception is java.lang.OutOfMemoryError: GC overhead limit exceeded

整個服務基本可以說處於不可用狀態,任何請求過來幾乎都會報oom,但是這跟重啟有什麼關係呢?是誰觸發了重啟呢?這裡我暫時賣個關子,後面進行解答。 

 

3.k8s健康檢查介紹

我們的服務部署在k8s中,k8s可以對容器執行定期的診斷,要執行診斷,kubelet 呼叫由容器實現的 Handler (處理程式)。有三種型別的處理程式:

  • ExecAction:在容器內執行指定命令。如果命令退出時返回碼為 0 則認為診斷成功。

  • TCPSocketAction:對容器的 IP 地址上的指定埠執行 TCP 檢查。如果埠開啟,則診斷被認為是成功的。

  • HTTPGetAction:對容器的 IP 地址上指定埠和路徑執行 HTTP Get 請求。如果響應的狀態碼大於等於 200 且小於 400,則診斷被認為是成功的。

每次探測都將獲得以下三種結果之一:

  • Success(成功):容器通過了診斷。

  • Failure(失敗):容器未通過診斷。

  • Unknown(未知):診斷失敗,因此不會採取任何行動。

針對執行中的容器,kubelet 可以選擇是否執行以下三種探針,以及如何針對探測結果作出反應:

  • livenessProbe:指示容器是否正在執行。如果存活態探測失敗,則 kubelet 會殺死容器, 並且容器將根據其重啟策略決定未來。如果容器不提供存活探針, 則預設狀態為 Success。

  • readinessProbe:指示容器是否準備好為請求提供服務。如果就緒態探測失敗, 端點控制器將從與 Pod 匹配的所有服務的端點列表中刪除該 Pod 的 IP 地址。初始延遲之前的就緒態的狀態值預設為 Failure。如果容器不提供就緒態探針,則預設狀態為 Success。

  • startupProbe: 指示容器中的應用是否已經啟動。如果提供了啟動探針,則所有其他探針都會被 禁用,直到此探針成功為止。如果啟動探測失敗,kubelet 將殺死容器,而容器依其 重啟策略進行重啟。如果容器沒有提供啟動探測,則預設狀態為 Success。

以上探針介紹內容來源於https://kubernetes.io/zh/docs/concepts/workloads/pods/pod-lifecycle/#container-probes

 

看完探針的相關介紹,可以基本回答上面的疑點“oom和重啟有什麼關係?”,是livenessProbe的鍋,簡單描述一下為什麼:

  1. 服務啟動;

  2. k8s通過livenessProbe中配置的健康檢查Handler做定期診斷(我們配置的是HttpGetAction);

  3. 由於oom所以HttpGetAction返回的http status code是500,被k8s認定為Failure(失敗)-容器未通過診斷;

  4. k8s認為pod不健康,決定“殺死”它然後重新啟動。

 

這是服務的Deployment.yml中關於livenessProbe和restartPolicy的配置

livenessProbe:
  failureThreshold: 5
  httpGet:
    path: /health
    port: 8080
    scheme: HTTP
  initialDelaySeconds: 180
  periodSeconds: 20
  successThreshold: 1
  timeoutSeconds: 10

restartPolicy: Always

  

4.第一次優化

記憶體溢位無外乎記憶體不夠用了,而這種不夠用又粗略分兩種情況:

  1. 存在記憶體洩漏情況,本來應該清理的物件但是並沒有被清理,比如HashMap以自定義物件作為Key時對hashCode和equals方法處理不當時可能會發生;

  2. 記憶體確實不夠用了,比如訪問量突然上來了;

由於我們這個是一個老服務,而且在多個客戶私有化環境都部署過,都沒出過這個問題,所以我直接排除了記憶體洩漏的情況,那就將目光投向第二種“記憶體確實不夠用”,通過對比訪問日誌和詢問業務人員後得知最近客戶在大力推廣系統,所以訪問量確實是上來了。

 

“不要一開始就陷入技術人員的固化思維,認為是程式存在問題”

 

知道了原因那解決手段也就很粗暴了,加記憶體唄,分分鐘改完重新發布。

 

 

終於釋出完成,我開啟監控平臺檢視服務的執行情況,這次日誌裡確實沒有oom的字樣,本次優化以迅雷不及掩耳之勢這麼快就完了?果然是我想多了,一陣過後我眼睜睜看著pod再次重啟,但詭異的是程式日誌裡沒有oom,這一次是什麼造成了它重啟呢?

 

我使用kubectl describe pod命令檢視一下pod的詳細資訊,重點關注Last State,裡面包括上一次的退出原因和退回code。

 

可以看到上一次退出是由於OOMKilled,字面意思就是pod由於記憶體溢位被kill,這裡的OOMKilled和之前提到的程式日誌中輸出的oom異常可千萬不要混為一談,如果pod 中的limit 資源設定較小,會執行記憶體不足導致 OOMKilled,這個是k8s層面的oom,這裡藉助官網的文件順便介紹一下pod和容器中的記憶體限制。

 

以下pod記憶體限制內容來源於https://kubernetes.io/zh/docs/tasks/configure-pod-container/assign-memory-resource/ 

要為容器指定記憶體請求,請在容器資源清單中包含 resources:requests 欄位。同理,要指定記憶體限制,請包含 resources:limits

以下deployment.yml將建立一個擁有一個容器的 Pod。容器將會請求 100 MiB 記憶體,並且記憶體會被限制在 200 MiB 以內:

apiVersion: v1
kind: Pod
metadata:
  name: memory-demo
  namespace: mem-example
spec:
  containers:
  - name: memory-demo-ctr
    image: polinux/stress
    resources:
      limits:
        memory: "200Mi"
      requests:
        memory: "100Mi"
    command: ["stress"]
    args: ["--vm", "1", "--vm-bytes", "150M", "--vm-hang", "1"]

當節點擁有足夠的可用記憶體時,容器可以使用其請求的記憶體。但是,容器不允許使用超過其限制的記憶體。如果容器分配的記憶體超過其限制,該容器會成為被終止的候選容器。如果容器繼續消耗超出其限制的記憶體,則終止容器。如果終止的容器可以被重啟,則 kubelet 會重新啟動它,就像其他任何型別的執行時失敗一樣。

迴歸到我們的場景中來講,雖然把jvm記憶體提高了,但是其執行環境(pod、容器)的記憶體限制並沒有提高,所以自然是達不到預期狀態的,解決方式也是很簡單了,提高deployment.yml中memory的限制,比如jvm中-Xmx為1G,那memory的limits至少應該大於1G。

 

至此,第一次優化算是真正告一段落。

 

5.第二次優化

第一次優化只給我們帶來了短暫的平靜,重啟次數確實有所下降,但是離我們追求的目標還是相差甚遠,所以亟需來一次更徹底的優化,來捍衛技術人員的尊嚴,畢竟我們都是頭頂別墅的人。

 頭頂撐不住的時候,吃點好的補補

  

上一次頻繁重啟是因為記憶體不足導致大量的oom異常,最終k8s健康檢查機制認為pod不健康觸發了重啟,優化手段就是加大jvm和pod的記憶體,這一次的重啟是因為什麼呢?

 

前面說過k8s對http形式的健康檢查地址做探測時,如果響應的狀態碼大於等於 200 且小於 400,則診斷被認為是成功的,否則就認為失敗,這裡其實忽略了一種極其普遍的情況“超時”,如果超時了也一併會歸為失敗。

 

為什麼這裡才引出超時呢,因為之前日誌中有大量的報錯,很直觀的可以聯想到健康檢查一定失敗,反觀這次並沒有直接證據,逼迫著發揮想象力(其實後來知道通過kubectl describe pod是可以直接觀測到超時這種情況的)。

現在我們就去反推有哪些情況會造成超時:

1.cpu 100%,這個之前確實遇到過一次,是因為宿主機cpu 100%,造成大量pod停止響應,最終大面積重啟;

2.網路層面出了問題,比如tcp佇列被打滿,導致請求得不到處理。感興趣的可以參考我之前的文章CLOSE_WAIT導致服務假死

3.web容器比如tomcat、jetty的執行緒池飽和了,這時後來的任務會堆積線上程池的佇列中;

4.jvm卡頓了,比如讓開發聞風喪膽的fullgc+stw;

 

以上四種只是通過我的認知列舉的,水平有限,更多情況歡迎大家補充。

現在我們一一排除,揪出元凶

 

1.看了監控宿主機負載正常,cpu正常,所以排除宿主機的問題;

2.ss -lnt檢視tcp佇列情況,並沒有堆積、溢位情況,排除網路層面問題;

3.jstack檢視執行緒情況,worker執行緒稍多但沒有到最大值,排除執行緒池滿的情況;

4.jstat gcutil檢視gc情況,gc比較嚴重,老年代gc執行一次平均耗時1秒左右,持續時間50s到60s左右嫌疑非常大。

 

通過上面的排除法暫定是gc帶來的stw導致jvm卡頓,最終導致健康檢查超時,順著這個思路我們先優化一把看看效果。

 

開始之前先補一張gc耗時的截圖,為了檢視的直觀性,此圖由arthas的dashboard產生。

 

說實話我對gc是沒有什麼調優經驗的,雖然看過比較多的文章,但是連紙上談兵都達不到,這次也是硬著頭皮進行一次“調參”,調優這件事真是不敢當。

 

具體怎麼調參呢,通過上面gc耗時的分佈,很直觀的拿到一個訊息,老年代的gc耗時有點長,而且次數比較頻繁,雖然圖裡只有40次,但是相對於這個服務的啟動時間來講已經算頻繁了,所以目標就是降低老年代gc頻率。

從我瞭解的gc知識來看,老年代gc頻繁是由於物件過早晉升導致,本來應該等到age達到晉升閾值才晉升到老年代的,但是由於年輕代記憶體不足,所以提前晉升到了老年代,晉升率過高是導致老年代gc頻繁的主要原因,所以最終轉化為如何降低晉升率,有兩種辦法:

1.增大年輕代大小,物件在年輕代得到回收,只有生命週期長的物件才進入老年代,這樣老年代增速變慢,gc頻率也就降下來了;

2.優化程式,降低物件的生存時間,儘量在young gc階段回收物件。

 

由於我對這個服務並不是很熟悉,所以很自然的傾向於方法1“調整記憶體”,具體要怎麼調整呢,這裡借用一下美團技術部落格中提到的一個公式來拋磚一下:

圖片內容來源於https://tech.meituan.com/2017/12/29/jvm-optimize.html

 

結合之前的那張gc耗時圖可以知道這個服務活躍資料大小為750m,進而得出jvm記憶體各區域的配比如下:

年輕代:750m*1.5 = 1125m

老年代:750m*2.5 = 1875m

 

接下來通過調整過的jvm記憶體配比重新發布驗證效果,通過一段時間的觀察,老年代gc頻率很明顯降下來了,大部分物件在新生代被回收,整體stw時間減少,執行一個多月再沒有遇到自動重啟的情況,由此也驗證了我之前的猜測“因為持續的gc導致健康檢查超時,進而觸發重啟”。

 

至此,第二次優化告一段落。

 6.第三次優化

第二次優化確實給我們帶來了一段時間的安寧,後續的一個多月當機率的統計不至於啪啪打架構部的臉。

 

 剛安生幾天,這不又來活了

 

有運維反饋某服務在北京客戶的私有化部署環境有重啟現象,頻率基本上在2天一次,接收到這個訊息以後我們立馬重視起來,先確定兩個事:

1.個例還是普遍現象-個例,只在這個客戶環境出現

2.會不會和前兩次優化的問題一樣,都是記憶體設定不合適導致的-不是,新服務,記憶體佔用不高,gc也還好

 

結合前面的兩個推論“個例”+“新服務,各項指標暫時正常“,我懷疑會不會是給這個客戶新做的某個功能存在bug,因為目前使用頻率不高,所以積攢一段時間才把服務拖垮。帶著這個疑惑我採取了守株待兔的方式,shell寫一個定時任務,每5s輸出一下關鍵指標資料,定時任務如下:

#!/bin/bash

while true ; do
/bin/sleep 5

netstat -n | awk '/^tcp/ {++S[$NF]} END {for(a in S) print a, S[a]}'  >> netstat.log
ss -lnt  >> ss.log
jstack 1 >> jstack.log
done

主要關注的指標有網路情況、tcp佇列情況、執行緒棧情況。

 

就這樣,一天以後這個服務終於重啟了,我一一檢查netstat.log,ss.log,jstack.log這幾個檔案,在jstack.log中問題原因剝繭抽絲般顯現出來,貼一段stack資訊讓大家一睹為快:

"qtp1819038759-2508" #2508 prio=5 os_prio=0 tid=0x00005613a850c800 nid=0x4a39 waiting on condition [0x00007fe09ff25000]
   java.lang.Thread.State: WAITING (parking)
        at sun.misc.Unsafe.park(Native Method)
        - parking to wait for  <0x00000007221fc9e8> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)
        at java.util.concurrent.locks.LockSupport.park(LockSupport.java:175)
        at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:2044)
        at org.apache.http.pool.AbstractConnPool.getPoolEntryBlocking(AbstractConnPool.java:393)
        at org.apache.http.pool.AbstractConnPool.access$300(AbstractConnPool.java:70)
        at org.apache.http.pool.AbstractConnPool$2.get(AbstractConnPool.java:253)
        - locked <0x00000007199cc158> (a org.apache.http.pool.AbstractConnPool$2)
        at org.apache.http.pool.AbstractConnPool$2.get(AbstractConnPool.java:198)
        at org.apache.http.impl.conn.PoolingHttpClientConnectionManager.leaseConnection(PoolingHttpClientConnectionManager.java:306)
        at org.apache.http.impl.conn.PoolingHttpClientConnectionManager$1.get(PoolingHttpClientConnectionManager.java:282)
        at org.apache.http.impl.execchain.MainClientExec.execute(MainClientExec.java:190)
        at org.apache.http.impl.execchain.ProtocolExec.execute(ProtocolExec.java:186)
        at org.apache.http.impl.execchain.RedirectExec.execute(RedirectExec.java:110)
        at org.apache.http.impl.client.InternalHttpClient.doExecute(InternalHttpClient.java:185)
        at org.apache.http.impl.client.CloseableHttpClient.execute(CloseableHttpClient.java:83)
        at com.aliyun.oss.common.comm.DefaultServiceClient.sendRequestCore(DefaultServiceClient.java:125)
        at com.aliyun.oss.common.comm.ServiceClient.sendRequestImpl(ServiceClient.java:123)
        at com.aliyun.oss.common.comm.ServiceClient.sendRequest(ServiceClient.java:68)
        at com.aliyun.oss.internal.OSSOperation.send(OSSOperation.java:94)
        at com.aliyun.oss.internal.OSSOperation.doOperation(OSSOperation.java:149)
        at com.aliyun.oss.internal.OSSOperation.doOperation(OSSOperation.java:113)
        at com.aliyun.oss.internal.OSSObjectOperation.getObject(OSSObjectOperation.java:273)
        at com.aliyun.oss.OSSClient.getObject(OSSClient.java:551)
        at com.aliyun.oss.OSSClient.getObject(OSSClient.java:539)
        at xxx.OssFileUtil.downFile(OssFileUtil.java:212)

大量的執行緒hang在了        org.apache.http.impl.conn.PoolingHttpClientConnectionManager$1.get(PoolingHttpClientConnectionManager.java:282

這個是做什麼的呢?這個正是HttpClient中的連線池滿了的跡象,執行緒在等待可用連線,最終導致jetty的執行緒被打滿,造成服務假死,自然是不能及時響應健康檢查,最終觸發k8s的重啟策略。

 

最終通過排查程式碼發現是由於使用阿里雲oss sdk不規範導致連線沒有按時歸還,久而久之就造成了連線池、執行緒池被佔滿的情況,至於為什麼只有北京客戶有這個問題是因為只有這一家配置了oss儲存,而且這個屬於新支援的功能,目前尚處於試點階段,所以短時間量不大,1到2天才出現一次重啟事故。

 

解決辦法很簡單,就是及時關閉ossObject,防止連線洩漏。

7.總結

通過前前後後一個多月的持續優化,服務的可用性又提高了一個臺階,於我而言收穫頗豐,對於jvm知識又回顧了一遍,也能結合以往知識進行簡單的調參,對於k8s這一黑盒,也不再那麼陌生,學習了基本的概念和一些簡單的運維指令,最後還是要說一句“工程師對於自己寫的每一行程式碼都要心生敬畏,否則可能就會給公司和客戶帶來資損”。

 

8.推薦閱讀


從實際案例聊聊Java應用的GC優化-美團技術團隊

分享一次排查CLOSE_WAIT過多的經驗

 

  

  

相關文章