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

導讀

本文介紹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配置的最大記憶體大。

堆上記憶體洩漏

堆上記憶體洩露是最常見的，申請的物件引用和記憶體全在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引用。

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

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

RPC連線使用完後未關閉

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

堆外記憶體洩露

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分配了太多記憶體。

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申請的堆外記憶體大小。

然後用命令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，記錄哪些記憶體未被釋放。

效能最佳化

arthas

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

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

另外，常用最佳化小建議：熱點函式避免使用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，則時間減少一半。

tcpdump

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

用命令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請求多做了哪些事情即可。

最後透過分析日誌和閱讀程式碼發現，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%。

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

然後計算出使用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的執行緒池修改即可。

當機

被其他程式殺

在生產環境發生過程式被清理指令碼殺掉。排查工具有兩個：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。從這些資訊並不能找到相應的程式，因為指令碼往往執行完就停止，生命週期非常短。

接下來使用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啟動的，也就是說定時任務執行了某些指令碼殺了程式。但仍然不知道定時任務啟動了哪個指令碼殺了程式。

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

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

呼叫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表示關閉該功能。

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

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

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

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

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

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

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

因此問題出在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導致程式掛掉。

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

接著分析為何有兩萬多個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的原因找到。

死鎖

log4j導致的死鎖

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

封裝不嚴謹導致的死鎖

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

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

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

參考

[1]

[2]

[3]

[4]