導讀

本文介紹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 https://github.com/jemalloc/jemalloc.gitgit checkout 5.2.1./configure --enable-prof --enable-stats --enable-debug --enable-fillmake && make install然后在進程啟動腳本里，添加如下命令，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 :%dn", ctime(gettimeofday_s()), sig_name, pid_name , sig_pid, execname(), pid(), uid());printf("parent of sender: %s(%d)n", pexecname(), ppid());printf("task_ancestry:%sn", 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方法。