記一次生産環境頻繁耗時GC導緻的周期性響應緩慢問題

• • 1.問題來源與背景
  • 2.問題查詢與定位
  • • • 2.1 日志中心查詢
      • 2.2 容器日志查詢
  • 3.問題排查
  • • • 3.1 網絡排查
      • 3.2 日志觀察
  • 4.總結

1.問題來源與背景

服務使用K8s叢集部署，重要的服務采用多節點負載的形式搭建。出問題的節點持續運作時間将近半年。某一天的早上收到預警資訊，說k8s某節點服務不可用，大家立馬都緊張起來了。

2.問題查詢與定位

2.1 日志中心查詢

錯誤日志：

日志中顯示7點多的時候 頻繁出現通路逾時的現象 。

耗時日志：

耗時日志中也顯示7點多的時候出現了大量的響應時間過長的請求。

2.2 容器日志查詢

上伺服器檢視某個節點的日志，發現有很多逾時的請求出現。而這些出問題的節點 均為網關api-gateway節點。然後通過請求鍊路日志進行分析，發現問題大機率就出在網關節點上面。

3.問題排查

3.1 網絡排查

step 1

在主控端使用ping pod ip的方式，發現是正常的。然後執行docker容器中逾時的那條curl請求，這裡沒有使用svc的ip，使用了pod的ip位址。

curl 10.233.23.3:4000

發現偶爾會出現逾時的現象。經過多次嘗試，觸發其逾時後，總結出規律：這個端口逾時現象是呈周期性發生的。

step 2

周期性出現逾時現象看起來并不像是網絡問題，為了進一步排除網絡問題，決定在pod中的docker容器内安裝另一個web服務，我選擇了安裝一個nginx。

安裝完nginx後，啟動，暴露一個端口80。

同樣在主控端使用ping pod ip的方式，發現是正常的。然後開始執行curl指令。使用腳本多次執行

curl 10.233.23.3:80

指令後發現80端口是正常的，沒有出現過一次逾時現象。而同時curl 4000端口會發現，逾時現象還是會周期性發生。

step 3

通過上述過程可以基本排除是k8s網絡引起的逾時現象，但是我們運作的這個網關節點已經半年多沒有更新過代碼了。為什麼會突然出現這樣的情況呢？

3.2 日志觀察

本想觀察網關的曆史日志，但是網關節點的日志太龐大了，無法快速定位到想要排查的地方，而且在日志系統中也發現不了引發逾時現象的原因。

這個時候剛好看到了網關服務節點下有一個gc日志可以檢視。于是開始觀察gc日志。

由于之前沒有這方面的經驗，是以隻能臨陣磨槍，去學習看gc日志。

我們使用的是CMS垃圾回收器，是以參考了CMS垃圾回收器詳解這篇文章去學習看gc日志。

看完日志之後，特别欣喜，因為gc日志确實有問題：

從gc日志中，粗略觀察出來有耗時特别長的gc，這個時間長達9s，而仔細觀察gc的分步日志，會發現這個CMS gc是在執行年輕代gc的時候釋放記憶體失敗了，是以才觸發了Full gc，而Full gc 是會STW的，剛好耗時又特别長，跟逾時現象更加貼切的是，它兩次長耗時gc的時間間隔剛好是之前觀察出來的 周期性逾時的時間間隔。于是問題就基本上可以定位為JVM的問題了。

4.總結

為什麼一個java程式會在長時間運作時産生gc失敗的問題呢？

#######jvm問題對我來講可能比較陌生，暫時還沒什麼時間去研究，後面有時間研究了再進行記錄。