記一次k8s pod頻繁重啟的優化之旅
關鍵詞：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的鍋，簡單描述一下為什麼：
-
服務啟動；
-
k8s通過livenessProbe中配置的健康檢查Handler做定期診斷（我們配置的是HttpGetAction）；
-
由於oom所以HttpGetAction返回的http status code是500，被k8s認定為Failure（失敗）-容器未通過診斷；
-
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.第一次優化
記憶體溢位無外乎記憶體不夠用了，而這種不夠用又粗略分兩種情況：
-
存在記憶體洩漏情況，本來應該清理的物件但是並沒有被清理，比如HashMap以自定義物件作為Key時對hashCode和equals方法處理不當時可能會發生；
-
記憶體確實不夠用了，比如訪問量突然上來了；
由於我們這個是一個老服務，而且在多個客戶私有化環境都部署過，都沒出過這個問題，所以我直接排除了記憶體洩漏的情況，那就將目光投向第二種“記憶體確實不夠用”，通過對比訪問日誌和詢問業務人員後得知最近客戶在大力推廣系統，所以訪問量確實是上來了。
“不要一開始就陷入技術人員的固化思維，認為是程式存在問題”
知道了原因那解決手段也就很粗暴了，加記憶體唄，分分鐘改完重新發布。
終於釋出完成，我開啟監控平臺檢視服務的執行情況，這次日誌裡確實沒有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.推薦閱讀