1. 程式人生 > >一次容器化springboot程式OOM問題探險

一次容器化springboot程式OOM問題探險

背景

運維人員反饋一個容器化的java程式每跑一段時間就會出現OOM問題,重啟後,間隔大概兩天後復現。

問題調查

一查日誌

由於是容器化部署的程式,登上主機後使用docker logs ContainerId檢視輸出日誌,並沒有發現任何異常輸出。 使用docker stats檢視容器使用的資源情況,分配了2G大小,也沒有發現異常。

二缺失的工具

打算進入容器內部一探究竟,先使用docker ps 找到java程式的ContainerId
,再執行docker exec -it ContainerId /bin/bash進入容器。進入後,本想著使用jmap、jstack 等JVM分析命令來診斷,結果發現命令都不存在,顯示如下:

bash: jstack: command not found
bash: jmap: command not found
bash: jps: command not found
bash: jstat: command not found

突然意識到,可能打映象的時候使用的是精簡版的JDK,並沒有這些jVM分析工具,但是這仍然不能阻止我們分析問題的腳步,此時docker cp命令就派上用場了,它的作用是:在容器和宿主機之間拷貝檔案。這裡使用的思路是:拷貝一個新的jdk到容器內部,目的是為了執行JVM分析命令,參照用法如下:

Usage:  docker cp [OPTIONS] CONTAINER:SRC_PATH DEST_PATH|-
        docker cp [OPTIONS] SRC_PATH|- CONTAINER:DEST_PATH [flags]

有了JVM工具,我們就可以開始分析咯。

三查GC情況

通過jstat檢視gc情況

 bin/jstat -gcutil 1 1s

看樣子沒有什麼問題,full gc也少。再看一下物件的佔用情況,由於是容器內部,程序號為1,執行如下命令:

bin/jmap -histo 1 |more 

發現ByteBuffer物件佔用最高,這是異常點一。

四查執行緒快照情況
  • 通過jstack檢視執行緒快照情況。
 bin/jstack -l 1 > thread.txt

下載快照,這裡推薦一個線上的執行緒快照分析網站。

https://gceasy.io

上傳後,發現建立的執行緒近2000個,且大多是TIMED_WAITING狀態。感覺逐漸接近真相了。 點選詳情發現有大量的kafka-producer-network-thread | producer-X 執行緒。如果是低版本則是大量的ProducerSendThread執行緒。(後續驗證得知),可以看出這個是kafka生產者建立的執行緒,如下是生產者傳送模型:

根據生產者的傳送模型,我們知道,這個sender執行緒主要做兩個事,一是獲取kafka叢集的Metadata共享給多個生產者,二是把生產者送到本地訊息佇列中的資料,傳送至遠端叢集。而本地訊息佇列底層的資料結構就是java NIO的ByteBuffer。

這裡發現了異常點二:建立過多kafka生產者。

由於沒有業務程式碼,決定寫一個Demo程式來驗證這個想法,定時2秒建立一個生產者物件,傳送當前時間到kafka中,為了更好的觀察,啟動時指定jmx埠,使用jconsole來觀察執行緒和記憶體情況,程式碼如下:

nohup java -jar -Djava.rmi.server.hostname=ip 
 -Dcom.sun.management.jmxremote.port=18099
 -Dcom.sun.management.jmxremote.rmi.port=18099
 -Dcom.sun.management.jmxremote.ssl=false
 -Dcom.sun.management.jmxremote.authenticate=false -jar
 com.hyq.kafkaMultipleProducer-1.0.0.jar   2>&1 &

連線jconsole後觀察,發現執行緒數一直增長,使用記憶體也在逐漸增加,具體情況如下圖:

故障原因回顧

分析到這裡,基本確定了,應該是業務程式碼中迴圈建立Producer物件導致的。
在kafka生產者傳送模型中封裝了 Java NIO中的 ByteBuffer 用來儲存訊息資料,ByteBuffer的建立是非常消耗資源的,儘管設計了BufferPool來複用,但也經不住每一條訊息就建立一個buffer物件,這也就是為什麼jmap顯示ByteBuffer佔用記憶體最多的原因。

總結

在日常的故障定位中,多多使用JDK自帶的工具,來幫助我們輔助定位問題。一些其他的知識點:
jmap -histo顯示的物件含義:

[C 代表  char[]
[S 代表 short[]
[I 代表 int[]
[B 代表 byte[]
[[I 代表 int[][]

如果匯出的dump檔案過大,可以將MAT上傳至伺服器,分析完畢後,下載分析報告檢視,命令為:

./mat/ParseHeapDump.sh active.dump  org.eclipse.mat.api:suspects
org.eclipse.mat.api:overview org.eclipse.mat.api:top_components

可能儘快觸發Full GC的幾種方式

1) System.gc();或者Runtime.getRuntime().gc();

2 ) jmap -histo:live或者jmap -dump:live。
這個命令執行,JVM會先觸發gc,然後再統計資訊。
3) 老生代記憶體不足的時候