案例分享-full gc導致k8s pod重啟

在之前的記一次k8s pod頻繁重啟的最佳化之旅中分享過對於pod頻繁重啟的一些案例，最近又遇到一例，繼續分享出來希望能給大家帶來些許收穫。

問題現象

報警群裡突然顯示某pod頻繁重啟，我隨即上去檢視日誌，主要分這麼幾步：

1.檢視pod重啟的原因，kubectl descirbe pod

Last State:     Terminated
      Reason:       Error
      Exit Code:    137

上面的Reason：Error太寬泛了，不能直觀的知道原因，Exit code：137一般表示程式被 SIGKILL 中斷訊號殺死，異常原因可能為：

https://cloud.tencent.com/document/product/457/42945

首先排除OOMKilled情況，剩餘的就是livenessProbe（存活檢查）失敗。

2.檢視pod事件，kubectl descirbe pod，重點關注輸出的Events部分

Warning  Unhealthy  2m56s (x8 over 7m16s)   kubelet            Liveness probe failed: Get http://10.244.11.136:8080/jc_actuator_1/health: net/http: request canceled (Client.Timeout exceeded while awaiting headers)
Normal   Killing    2m56s                   kubelet            Container enterprise-service failed liveness probe, will be restarted

熟悉的健康檢查失敗（超時），是什麼導致超時呢，繼續找日誌。

3.結合之前的排查經驗，我認為gc的嫌疑最大，所以檢視gc日誌

貼一部分日誌，可以看到Full GC很繁忙，而且每次結束後記憶體幾乎沒有釋放，應用已經是處於停擺狀態，接下來要做的就是找出Full GC的兇手。

2023-04-22T14:30:58.772+0000: 574.764: [Full GC (Allocation Failure) 2023-04-22T14:30:58.772+0000: 574.764: [Tenured: 2097151K->2097151K(2097152K), 3.6358812 secs] 2569023K->2568977K(2569024K), [Metaspace: 119379K->119379K(1163264K)], 3.6359987 secs] [Times: user=3.64 sys=0.00, real=3.63 secs] 
2023-04-22T14:31:02.410+0000: 578.402: [Full GC (Allocation Failure) 2023-04-22T14:31:02.410+0000: 578.402: [Tenured: 2097151K->2097151K(2097152K), 3.5875116 secs] 2569023K->2568980K(2569024K), [Metaspace: 119379K->119379K(1163264K)], 3.5876388 secs] [Times: user=3.59 sys=0.00, real=3.59 secs] 
2023-04-22T14:31:05.999+0000: 581.991: [Full GC (Allocation Failure) 2023-04-22T14:31:05.999+0000: 581.991: [Tenured: 2097152K->2097151K(2097152K), 3.5950824 secs] 2569024K->2568987K(2569024K), [Metaspace: 119379K->119379K(1163264K)], 3.5951774 secs] [Times: user=3.59 sys=0.00, real=3.60 secs] 
2023-04-22T14:31:09.596+0000: 585.587: [Full GC (Allocation Failure) 2023-04-22T14:31:09.596+0000: 585.587: [Tenured: 2097151K->2097151K(2097152K), 3.5822343 secs] 2569023K->2568849K(2569024K), [Metaspace: 119379K->119379K(1163264K)], 3.5823244 secs] [Times: user=3.58 sys=0.00, real=3.58 secs] 
2023-04-22T14:31:13.180+0000: 589.172: [Full GC (Allocation Failure) 2023-04-22T14:31:13.180+0000: 589.172: [Tenured: 2097151K->2097151K(2097152K), 3.6316461 secs] 2569020K->2568910K(2569024K), [Metaspace: 119380K->119380K(1163264K)], 3.6317393 secs] [Times: user=3.63 sys=0.00, real=3.64 secs] 
2023-04-22T14:31:16.813+0000: 592.805: [Full GC (Allocation Failure) 2023-04-22T14:31:16.813+0000: 592.805: [Tenured: 2097151K->2097151K(2097152K), 3.6070671 secs] 2569021K->2568907K(2569024K), [Metaspace: 119380K->119380K(1163264K)], 3.6071998 secs] [Times: user=3.60 sys=0.00, real=3.60 secs] 
2023-04-22T14:31:20.425+0000: 596.417: [Full GC (Allocation Failure) 2023-04-22T14:31:20.425+0000: 596.417: [Tenured: 2097151K->2097151K(2097152K), 4.7111087 secs] 2569020K->2568899K(2569024K), [Metaspace: 119381K->119381K(1163264K)], 4.7112440 secs] [Times: user=4.71 sys=0.00, real=4.71 secs] 
2023-04-22T14:31:25.142+0000: 601.133: [Full GC (Allocation Failure) 2023-04-22T14:31:25.142+0000: 601.133: [Tenured: 2097151K->2097151K(2097152K), 3.8752248 secs] 2569023K->2568899K(2569024K), [Metaspace: 119381K->119381K(1163264K)], 3.8753506 secs] [Times: user=3.88 sys=0.01, real=3.87 secs] 
2023-04-22T14:31:29.021+0000: 605.012: [Full GC (Allocation Failure) 2023-04-22T14:31:29.021+0000: 605.012: [Tenured: 2097151K->2097151K(2097152K), 3.5892311 secs] 2569023K->2568910K(2569024K), [Metaspace: 119381K->119381K(1163264K)], 3.5893335 secs] [Times: user=3.59 sys=0.00, real=3.59 secs] 
2023-04-22T14:31:32.612+0000: 608.604: [Full GC (Allocation Failure) 2023-04-22T14:31:32.612+0000: 608.604: [Tenured: 2097151K->2097151K(2097152K), 3.5236182 secs] 2569023K->2568915K(2569024K), [Metaspace: 119381K->119381K(1163264K)], 3.5237085 secs] [Times: user=3.52 sys=0.00, real=3.52 secs]

背景知識

我們的服務部署在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

尋找原因

前面提到是由於Full GC STW導致jvm無法提供服務，那我們就看看是什麼導致Full GC，具體的手段就是獲取heap dump檔案，然後分析，什麼時機去獲取呢？

這裡採用的辦法是守株待兔，開兩個視窗，一個盯著gc日誌，當看到有大量Full GC產生時在另一個視窗生成heap dump檔案。

接下來透過Eclipse MAT工具分析dump檔案

原因一目瞭然，是匯出excel導致，涉及的資料接近10w條，且列比較多。

分析程式碼

大概看了一下匯出的程式碼，問題集中在以下四點:

1.查詢資料沒有使用分頁；

2.使用的Apache poi工具本身效能不好，記憶體佔用過高；

3.匯出沒有限流，對於極度消耗資源的操作必須要控制併發，保護系統；

4.同步匯出，使用者等待時間過長時會選擇重試，對系統來講是雪上加霜。

改進措施

1.查詢分頁，保證往excel寫資料時記憶體中只會有一頁資料；

2.使用效能更好的工具，如easyexcel;

3.非同步匯出，控制同時匯出的併發數；

經過這三步改造以後，匯出導致的Full GC問題得以改善，上線一週再沒有發現由於大資料量的匯出導致的pod重啟問題。