Java記憶體洩漏、效能最佳化、當機死鎖的N種姿勢

樸所羅門發表於2020-08-10

導讀

本文介紹Java諸多最佳化例項:第一,排查堆上、堆外記憶體洩露;第二,使用arthas、jaeger、tcpdump、jstack做效能最佳化;第三,排查程式異常退出的原因,如被殺、System.exit、Java呼叫的C++發生Crash、Java內Crash;第四,排查死鎖的原因,如log4j死鎖、封裝不嚴謹導致的死鎖

記憶體洩漏

記憶體洩露在C++裡排查很簡單,用鉤子函式勾住記憶體分配和釋放函式malloc和free,統計哪些malloc的記憶體沒有free,就可以找出記憶體洩露的源頭。但在Java裡問題複雜的多,主要因為Java在記憶體之上有層JVM管理記憶體。

JVM先從作業系統申請大記憶體,接著自己管理這部分記憶體。所以Java程式的記憶體洩露分為兩種:堆上記憶體洩露、堆外記憶體洩露,而堆外記憶體洩露又分為兩種:Java使用堆外記憶體導致的記憶體洩露、Java程式使用C++導致的記憶體洩露。

分析記憶體洩露首先需要確認是堆上洩漏還是堆外洩露。可以透過jmap -heap pid確認,如下圖所示,老年代PS Old Generation使用率佔99.99%,再結合gc log,如果老年代回收不掉,基本確認為堆上記憶體洩露,也不排除程式本身需要這麼多記憶體,此時需要分析堆。而堆外記憶體洩露的顯著表現是top命令查出來的實體記憶體顯著比透過xmx配置的最大記憶體大。

Java記憶體洩漏、效能最佳化、當機死鎖的N種姿勢

堆上記憶體洩漏

堆上記憶體洩露是最常見的,申請的物件引用和記憶體全在JVM堆上,而物件使用完後,物件引用被其他長生命週期的物件一直拿著,導致無法從堆上釋放。首先用jdk/bin/jmap -dump:live,format=b,file=heap.hprof {pid},匯出堆裡所有活著的物件。然後用工具分析heap.hprof。

分析堆上記憶體洩露的主流工具有兩種:JDK自帶的bin目錄下的jvisualvm.exe、Eclipse的MemoryAnalyzer。MemoryAnalyzer更強大,可自動分析可疑的記憶體洩露。使用MemoryAnalyzer時,需要在MemoryAnalyzer.ini裡透過-Xmx引數配置最大記憶體,否則無法開啟大堆。接下來介紹堆上記憶體洩露的若干例項。

物件被靜態物件引用

使用MemoryAnalyzer自動分析記憶體洩露,報告如下,可以看到RaftServerMetrics佔了44.68%的記憶體,所有例項大小98M記憶體,且所有的RaftServerMetrics例項被一個ConcurrentHashMap引用。

Java記憶體洩漏、效能最佳化、當機死鎖的N種姿勢

Java記憶體洩漏、效能最佳化、當機死鎖的N種姿勢

接著在直方圖裡過濾RaftServerMetrics,共找到2065個例項。

Java記憶體洩漏、效能最佳化、當機死鎖的N種姿勢

然後右鍵RaftServerMetrics->Merge shortest path to GC Roots ->with all references查詢所有引用RaftServerMetrics的地方,結果如下,可看到所有的RaftServerMetrics例項被變數metricsMap引用,問題原因是RaftServerMetrics使用完後,未從靜態變數metricsMap裡刪除。

Java記憶體洩漏、效能最佳化、當機死鎖的N種姿勢

RPC連線使用完後未關閉

MemoryAnalyzer自動分析記憶體洩露時,有時並不能準確的找到,此時需要自己分析哪些物件佔用記憶體過多。下圖是使用jvisualvm.exe開啟堆的結果,檢視數目或者記憶體異常的物件,可以看到很多物件數目都是111580個,且最後一列顯示的記憶體佔用大,從物件的包分析,都和netty有關,且是client相關的物件,基本確認這些物件和記憶體洩露有關。進一步分析程式碼,發現大量RPC連線使用完後未關閉。

Java記憶體洩漏、效能最佳化、當機死鎖的N種姿勢

堆外記憶體洩露

Java使用堆外記憶體

JDK提供繞過JVM直接在作業系統申請記憶體的介面,例如透過Unsafe類的allocateMemory、freeMemory直接分配、釋放記憶體,記憶體物件的引用在堆上,但記憶體在堆外。排查此類記憶體洩露,首先開啟:

-XX:NativeMemoryTracking=detail

然後jcmd pid VM.native_memory detail,打出記憶體分配資訊,注意NativeMemoryTracking顯示的記憶體不包含C++分配的記憶體。此處需要關注兩個點,第一,Total行的committed數值是否等於程式佔用的實體記憶體,如果不等,說明有C++等native code分配的記憶體,可參考Java呼叫C++元件 分析;第二,Native Memory Tracking的committed數值是否過大,如果過大,說明有Unsafe.allocateMemory分配了太多記憶體。

Java記憶體洩漏、效能最佳化、當機死鎖的N種姿勢

Unsafe.allocateMemory的使用場景有兩個:第一,封裝在DirectByteBuffer內;第二,業務直接使用Unsafe.allocateMemory。

DirectByteBuff通常被用於通訊框架如netty中,不僅可以減少GC壓力,而且避免IO操作時將物件從堆上複製到堆外。為了快速驗證是否DirectByteBuffer導致記憶體洩露,可使用引數-XX:MaxDirectMemorySize限制DirectByteBuffer分配的堆外記憶體大小,如果堆外記憶體仍然大於MaxDirectMemorySize,可基本排除DirectByteBuffer導致的記憶體洩露。

分析DirectByteBuffer的記憶體首先可用Java Mission Control,繫結到程式,並檢視DirectByteBuffer佔的記憶體如2.24GB。此處也可直接用MemoryAnalyzer開啟dump的堆,統計所有DirectByteBuffer的capacity之和,計算DirectByteBuffer申請的堆外記憶體大小。

Java記憶體洩漏、效能最佳化、當機死鎖的N種姿勢

然後用命令jdk/bin/jmap -dump:live,format=b,file=heap.hprof {pid},匯出堆裡所有活著的物件,並用MemoryAnalyzer開啟dump的堆,分析所有的DirectByteBuffe:Merge shortest path to GC Roots ->with all references。

如果排除DirectByteBuffer,那就是應用程式直接用Unsafe類的allocateMemory分配的記憶體,例如Spark的off heap memory[1]。此時可排查程式碼所有Unsafe.allocateMemory的地方。

Java呼叫C++元件

例如RocksDB採用C++實現,並透過JNI提供給Java呼叫的介面,如果Java透過JNI建立了新的RocksDB例項,RocksDB會啟動若干後臺執行緒申請、釋放記憶體,這部分記憶體都對Java不可見,如果發生洩漏,也無法透過dump jvm堆分析。

分析工具可採用google的gperftools,也可用jemalloc,本文采用jemalloc,首先安裝jemalloc到/usr/local/lib/libjemalloc.so。


git clone 

然後在程式啟動指令碼里,新增如下命令,LD_PRELOAD表示JVM申請記憶體時不再用glibc的ptmalloc,而是使用jemalloc。MALLOC_CONF的lg_prof_interval表示每次申請2^30Byte時生成一個heap檔案。



export LD_PRELOAD=/usr/local/lib/libjemalloc.soexport MALLOC_CONF=prof:true,lg_prof_interval:30


並在程式的啟動命令裡新增引數-XX:+PreserveFramePointer。程式啟動後,隨著不斷申請記憶體,會生成很多dump檔案,可把所有dump檔案透過命令一起分析:jeprof --show_bytes --pdf jdk/bin/java *.heap > leak.pdf。

leak.pdf如下所示,可看到所有申請記憶體的路徑,程式共申請過88G記憶體,而RocksDB申請了74.2%的記憶體,基本確定是不正常的行為,排查發現不斷建立新的RocksDB例項,共1024個,每個例項都在執行,最佳化方法是合併RocksDB例項。

需要注意的是,88G是所有申請過的記憶體,包含申請但已經被釋放的,因此透過該方法,大部分情況下能確定洩露源頭,但並不十分準確,準確的方法是在C++程式碼裡用鉤子函式勾住malloc和free,記錄哪些記憶體未被釋放。

Java記憶體洩漏、效能最佳化、當機死鎖的N種姿勢

效能最佳化

arthas

perf是最為普遍的效能分析工具,在Java裡可採用阿里的工具arthas進行perf,並生成火焰圖,該工具可在docker容器內使用,而系統perf命令在容器裡使用有諸多限制。

下載arthas-bin.zip[2],執行./a.sh,然後繫結到對應的程式,開始perf: profiler start,取樣一段時間後,停止perf: profiler stop。結果如下所示,可看到getServiceList耗了63.75%的CPU。

Java記憶體洩漏、效能最佳化、當機死鎖的N種姿勢

另外,常用最佳化小建議:熱點函式避免使用lambda表示式如stream.collect等、熱點函式避免使用正規表示式、避免把UUID轉成String在協議裡傳輸等。

jaeger

perf適用於查詢整個程式的熱點函式,但不適用於分析單次RPC呼叫的耗時分佈,此時就需要jaeger。

 jaeger是Uber開源的一個基於Go的分散式追蹤系統。jaeger基本原理是:使用者在自己程式碼裡插樁,並上報給jaeger,jaeger彙總流程並在UI顯示。非生產環境可安裝jaeger-all-in-one[3],資料都在記憶體裡,有記憶體溢位的風險。在需要追蹤的服務的啟動指令碼里export JAEGER_AGENT_HOST={jaeger服務所在的host}。

下圖為jaeger的UI,顯示一次完整的流程,左邊為具體的插樁名稱,右邊為每塊插裝程式碼耗時,可以看到最耗時的部分在including leader create container和including follower create container,這部分語義是leader建立完container後,兩個follower才開始建立container,而建立container非常耗時,如果改成leader和兩個follower同時建立container,則時間減少一半。

Java記憶體洩漏、效能最佳化、當機死鎖的N種姿勢


tcpdump

tcpdump常用來抓包分析,但也能用來最佳化效能。在我們的場景中,部署Ozone叢集(下一代分散式物件儲存系統),並讀資料,結果發現檔案越大讀速越慢,讀1G檔案,速度只有2.2M每秒,使用perf未發現線索。

Java記憶體洩漏、效能最佳化、當機死鎖的N種姿勢

用命令tcpdump -i eth0 -s 0 -A 'tcp dst port 9878 and tcp[((tcp[12:1] & 0xf0) >> 2):4] = 0x47455420' -w read.cap,該命令在讀200M檔案時會將所有GET請求匯出到read.cap檔案,然後用wireshark開啟read.cap,並過濾出HTTP協議,因為大部分協議都是TCP協議,用於傳輸資料,而HTTP協議用於請求開始和結束。

從下圖的wireshark介面,可看到讀200M檔案,共有10個GET請求:GET /goofys-bucket/test.dbf HTTP/1.1,每個GET請求讀20M檔案,每個GET請求讀完後回覆:HTTP/1.1 200 OK。第1個GET請求到達S3gateway時間為0.2287秒,第10個GET請求到達Ozone叢集時間為1.026458秒。第1個GET請求完成時間為1.869579秒,第10個GET請求完成時間為23.640925秒。

可見10個GET請求在1秒內全部到達Ozone叢集,但每個請求耗時越來越長。因此只需要分析後續的GET請求讀同樣大小的資料塊,比前序GET請求多做了哪些事情即可。

Java記憶體洩漏、效能最佳化、當機死鎖的N種姿勢

最後透過分析日誌和閱讀程式碼發現,Ozone採用的第三方庫commons-io採用read實現skip。例如讀第10個GET請求時,實際只需要讀[180M, 200M),但commons-io實現skip前180M時,會將前180M讀出來,導致第10個GET請求讀完整的[0M, 200M),因此GET請求越來越慢。最佳化後,效能提升一百倍。


jstack

jstack用來查詢執行緒狀態,但在極端情況下也可以用於效能最佳化。在部署服務時,發現程式迅速佔滿所有CPU,24核的機器程式使用CPU達到2381%。

Java記憶體洩漏、效能最佳化、當機死鎖的N種姿勢

CPU使用如此之高,無法執行arthas進行perf分析,只能採用其他策略。首先用top -Hp pid命令打出程式pid的所有執行緒及每個執行緒的CPU消耗。如下圖,第一列PID為執行緒號,%CPU列代表CPU消耗,注意該圖只是展示作用,該圖的程式並不是使用CPU達到2381%的程式,原程式的資訊當初沒儲存。

Java記憶體洩漏、效能最佳化、當機死鎖的N種姿勢

然後計算出使用CPU最高的執行緒號的十六進位制表示0x417,再用jstack -l pid > jstack.txt命令打出所有執行緒狀態,用0x417在jstack.txt查詢消耗CPU最高的執行緒,即下圖所示ThreadPoolExecutor裡的執行緒,該執行緒一直處於RUNNABLE,且佇列為empty,基本確認該部分執行緒出了問題,因為正常的執行緒不會一直空轉,狀態會有TIMED_WAITING的時刻。

因為執行緒堆疊不包含業務程式碼,都是JDK的原始碼,因此用執行緒堆疊搜尋JDK相關問題,最終發現是JDK8的Bug:JDK-8129861,該Bug在建立大小為0的執行緒池時容易觸發,因此在應用程式碼裡,將大小為0的執行緒池修改即可。

Java記憶體洩漏、效能最佳化、當機死鎖的N種姿勢

當機

被其他程式殺

在生產環境發生過程式被清理指令碼殺掉。排查工具有兩個:linux自帶的auditd和systemtap。

首先使用auditd,因為該工具簡單易用,不用安裝。使用service auditd status檢查服務狀態,如果未啟動可用service auditd restart啟動。然後使用命令:auditctl -a exit,always -F arch=b64 -S kill,監聽所有的Kill訊號。如下圖所示,從type=OBJ_PID行裡可以看到:捕捉到的Kill訊號殺的程式號opid=40442,執行緒名ocomm=”rocksdb:pst_st”,注意這裡打出的執行緒名而不是程式名。

從type=SYSCALL行裡可以看到:a1=9表示kill -9;發出kill -9的程式是exe=”/usr/bin/bash”,程式號是pid=98003。從這些資訊並不能找到相應的程式,因為指令碼往往執行完就停止,生命週期非常短。

Java記憶體洩漏、效能最佳化、當機死鎖的N種姿勢

接下來使用systemtap分析,systemtap需要安裝:yum install systemtap systemtap-runtime。先寫systemtap指令碼findkiller.stp,如下所示,該systemtap指令碼捕捉殺程式sig_pid的KILL訊號,並使用task_ancestry列印發出KILL訊號程式的所有祖先程式。


probe signal.send{if(sig_name == "SIGKILL" && sig_pid == target()) {printf("%s, %s was sent to %s (pid:%d) by %s (pid:%d) uid :%d\n", ctime(gettimeofday_s()), sig_name, pid_name , sig_pid, execname(), pid(), uid());printf("parent of sender: %s(%d)\n", pexecname(), ppid());printf("task_ancestry:%s\n", task_ancestry(pid2task(pid()), 1));  }}


然後stap -p4 findkiller.stp生成ko檔案:stap_XX.ko,有的機器需要將ko檔案補上簽名才能執行。然後執行:nohup staprun  -x 98120  stap_XX.ko >nohup.out 2>&1 &,此處的98120即為指令碼中的target()。

捕捉結果如下,從圖裡可以看出發出KILL命令的程式是透過crond啟動的,也就是說定時任務執行了某些指令碼殺了程式。但仍然不知道定時任務啟動了哪個指令碼殺了程式。

Java記憶體洩漏、效能最佳化、當機死鎖的N種姿勢

接下來再用auditd排查,使用命令:auditctl -a exit,always -F arch=b64 -S execve捕捉所有的系統呼叫,結果如下,最後一行是捕捉到殺程式opid=20286的訊號,從圖中可看出kill訊號附近出現的都是/data/tools/clean命令。

Java記憶體洩漏、效能最佳化、當機死鎖的N種姿勢

/data/tools/clean裡呼叫了若干指令碼,在每個指令碼里用打出當前指令碼名和程式號到crontab.pid裡。並和systemtap抓到的程式號62118對比,找到了KILL訊號是從kill_non_run_app.sh指令碼里發出。

Java記憶體洩漏、效能最佳化、當機死鎖的N種姿勢


呼叫System的exit

如果在Java程式裡顯式呼叫System.exit結束程式,可以用arthas排查。首先寫指令碼system_exit.as如下。



options unsafe truestack java.lang.System exit -n 1

執行命令nohup ./as.sh -f system_exit.as 69001 -b > system_exit.out 2>&1 &,即可監控程式69001呼叫的所有System.exit。


Java呼叫的C++發生Crash

此處發生的Crash案例和下文Java內Crash產生的原因一樣,但現象不一樣,大部分情況下,是Crash在C++程式碼,只產生core檔案,不產生Java內Crash的Crash log;少量情況下Crash在JVM裡,產生Java內Crash的Crash log。

如果Java透過JNI呼叫C++程式碼,在C++裡發生Crash,JVM有時不會產生任何資訊就退出,此時藉助作業系統產生的core file分析程式退出原因,但作業系統預設關閉該功能,如下圖所示core file size為0表示關閉該功能。

Java記憶體洩漏、效能最佳化、當機死鎖的N種姿勢

因此需要在程式的啟動指令碼里(隻影響當前程式)設定ulimit -c ulimited來設定core file的大小,啟動程式後,開啟/proc/{pid}/limits,檢視Max core file size的大小確認是否開啟。

Java記憶體洩漏、效能最佳化、當機死鎖的N種姿勢

當發生Crash時,會生成core.pid檔案,一般core.pid檔案會非常大,因為該檔案包含了所有虛擬記憶體大小,所以大於實體記憶體,如下圖所示core.44729共53GB。

Java記憶體洩漏、效能最佳化、當機死鎖的N種姿勢

接下來使用命令gdb bin/java core.44729開啟core檔案,發現是rocksdb start thread時掛的,掛在libstdc++裡,這是glibc庫,基本不可能出問題,因此該堆疊可能是表象,有其他原因導致start thread失敗。

Java記憶體洩漏、效能最佳化、當機死鎖的N種姿勢

注意到開啟core檔案時,有太多執行緒-LWP輕量級程式。

Java記憶體洩漏、效能最佳化、當機死鎖的N種姿勢

然後在gdb裡用info threads,發現有三萬多個執行緒,都在wait鎖狀態,基本確認三萬多個執行緒,導致記憶體太大,建立不出來新的執行緒,因此掛在start thread裡。

Java記憶體洩漏、效能最佳化、當機死鎖的N種姿勢

接著分析三萬多個執行緒都是什麼執行緒,隨機選幾十個執行緒,打出每個執行緒的堆疊,可以看到大部分執行緒都是jvm執行緒。因為rocksdb建立出來的執行緒是:

從/tmp/librocksdbjni8646115773822033422.so來的;而jvm建立出來的執行緒都是從/usr/java/jdk1.8.0_191-amd64/jre/lib/amd64/server/libjvm.so來的,這部分執行緒佔了大部分。

Java記憶體洩漏、效能最佳化、當機死鎖的N種姿勢

Java記憶體洩漏、效能最佳化、當機死鎖的N種姿勢


因此問題出在Java程式碼裡,產生core.pid檔案的程式,雖然沒有產生crash log,但也是因為Java 執行緒太多,導致C++程式碼建立執行緒時掛掉。至於為什麼Java執行緒太多請看Java內Crash。
另外,core.pid完整的保留了C++元件Crash時的現場,包括變數、暫存器的值等,如果真的因為C++元件有Bug而Crash,例如空指標等。首先自行找到C++原始碼,找出懷疑空指標的變數{variableName},透過在gdb裡執行命令:p {variableName},可以看出每個變數的值,從而找出空指標的變數。


Java內Crash

排查Java內Crash的原因如OOM等,需要配置JVM的如下引數:

-XX:ErrorFile
-XX:+HeapDumpOnOutOfMemoryError
-XX:HeapDumpPath。

JVM內發生Crash時,會在-XX:ErrorFile配置的路徑下生成crash log。而-XX:+HeapDumpOnOutOfMemoryError、-XX:HeapDumpPath用於發生OOM時生成Dump堆,用於還原現場。下圖所示為產生的crash log。可以看到建立執行緒時發生OutOfMemory導致程式掛掉。

Java記憶體洩漏、效能最佳化、當機死鎖的N種姿勢

從下圖crash log可以看到有兩萬四千個Datanode State Machine Thread執行緒都在等鎖。到此確認上文Java呼叫C++發生Crash 產生core.pid的程式和產生crash log的程式都是因為兩萬多個Datanode State Machine Thread掛掉。

Java記憶體洩漏、效能最佳化、當機死鎖的N種姿勢

接著分析為何有兩萬多個Datanode State Machine Thread,程式碼裡可以看到該執行緒用執行緒池newCacheThreadPool建立。該newCacheThreadPool在沒有執行緒可用,例如執行緒都在等鎖的情況下,會建立新的執行緒,因此建立了兩萬多個執行緒。接著分析Datanode State Machine Thread等的什麼鎖。在程式的執行緒數超過5000時,用jstack -l pid > jstack.txt打出所有執行緒的狀態。

可以看到幾乎所有Datanode State Machine Thread在等鎖,而只有一個Datanode State Machine Thread – 5500 拿到了鎖,但是卡在提交RPC請求submitRequest。至此 Java呼叫C++發生Crash 和Java內Crash的原因找到。

Java記憶體洩漏、效能最佳化、當機死鎖的N種姿勢

Java記憶體洩漏、效能最佳化、當機死鎖的N種姿勢

死鎖

log4j導致的死鎖

jstack打出的死鎖資訊如下所示。grpc-default-executor-14765執行緒拿到了log4j的鎖,在等RaftServerImpl的鎖;grpc-default-executor-14776執行緒拿到了RaftServerImpl的鎖,在等log4j的鎖,導致這兩個執行緒都拿到了對方等待的鎖,所以造成兩個執行緒死鎖。可以看出,僅僅打日誌的log4j,不釋放鎖是最值得懷疑的地方。最後發現log4j存在死鎖的缺陷[4]。該缺陷在log4j2得到解決,升級log4j即可。

Java記憶體洩漏、效能最佳化、當機死鎖的N種姿勢

Java記憶體洩漏、效能最佳化、當機死鎖的N種姿勢

封裝不嚴謹導致的死鎖

jstack打出的死鎖資訊如下所示。grpc-default-executor-3449執行緒拿到了RaftLog的鎖,在等DataBlockingQueue的鎖;SegmentedRaftLogWorker拿到了DataBlockingQueue的鎖,在等RaftLog的鎖。

Java記憶體洩漏、效能最佳化、當機死鎖的N種姿勢

Java記憶體洩漏、效能最佳化、當機死鎖的N種姿勢

這裡最值得懷疑的是SegmentedRaftLogWorker拿到了DataBlockingQueue的鎖卻不釋放,因為queue的操作只是在佇列裡增、刪、查元素。如下圖所示DataBlockingQueue的方法poll,使用的鎖是自己封裝的鎖AutoCloseableLock implement AutoCloseable,鎖的釋放依賴於AutoCloseableLock過載的close方法。

Java記憶體洩漏、效能最佳化、當機死鎖的N種姿勢

再看acquire方法,先用lock.lock()拿到鎖,再建立新的AutoCloseableLock物件,如果拿到鎖後,在建立新物件AutoCloseableLock時發生OOM等異常,鎖就無法釋放。

Java記憶體洩漏、效能最佳化、當機死鎖的N種姿勢


參考

[1]

[2]

[3]

[4]

來自 “ ITPUB部落格 ” ,連結:http://blog.itpub.net/69978212/viewspace-2710360/,如需轉載,請註明出處,否則將追究法律責任。

相關文章