這篇文章主要為大家展示了“Java中內(nèi)存泄漏、性能優(yōu)化、宕機(jī)死鎖的示例分析”，內(nèi)容簡而易懂，條理清晰，希望能夠幫助大家解決疑惑，下面讓小編帶領(lǐng)大家一起研究并學(xué)習(xí)一下“Java中內(nèi)存泄漏、性能優(yōu)化、宕機(jī)死鎖的示例分析”這篇文章吧。
內(nèi)存泄露在C++里排查很簡單，用鉤子函數(shù)勾住內(nèi)存分配和釋放函數(shù)malloc和free，統(tǒng)計哪些malloc的內(nèi)存沒有free，就可以找出內(nèi)存泄露的源頭。但在Java里問題復(fù)雜的多，主要因?yàn)镴ava在內(nèi)存之上有層JVM管理內(nèi)存。
JVM先從操作系統(tǒng)申請大內(nèi)存，接著自己管理這部分內(nèi)存。所以Java程序的內(nèi)存泄露分為兩種：堆上內(nèi)存泄露、堆外內(nèi)存泄露，而堆外內(nèi)存泄露又分為兩種：Java使用堆外內(nèi)存導(dǎo)致的內(nèi)存泄露、Java程序使用C++導(dǎo)致的內(nèi)存泄露。
分析內(nèi)存泄露首先需要確認(rèn)是堆上泄漏還是堆外泄露?？梢酝ㄟ^jmap -heap pid確認(rèn)，如下圖所示，老年代PS Old Generation使用率占99.99%，再結(jié)合gc log，如果老年代回收不掉，基本確認(rèn)為堆上內(nèi)存泄露，也不排除進(jìn)程本身需要這么多內(nèi)存，此時需要分析堆。而堆外內(nèi)存泄露的顯著表現(xiàn)是top命令查出來的物理內(nèi)存顯著比通過xmx配置的大內(nèi)存大。
堆上內(nèi)存泄露是最常見的，申請的對象引用和內(nèi)存全在JVM堆上，而對象使用完后，對象引用被其他長生命周期的對象一直拿著，導(dǎo)致無法從堆上釋放。首先用jdk/bin/jmap -dump:live,format=b,file=heap.hprof {pid}，導(dǎo)出堆里所有活著的對象。然后用工具分析heap.hprof。
分析堆上內(nèi)存泄露的主流工具有兩種：JDK自帶的bin目錄下的jvisualvm.exe、Eclipse的MemoryAnalyzer。MemoryAnalyzer更強(qiáng)大，可自動分析可疑的內(nèi)存泄露。使用MemoryAnalyzer時，需要在MemoryAnalyzer.ini里通過-Xmx參數(shù)配置大內(nèi)存，否則無法打開大堆。接下來介紹堆上內(nèi)存泄露的若干實(shí)例。
使用MemoryAnalyzer自動分析內(nèi)存泄露，報告如下，可以看到RaftServerMetrics占了44.68%的內(nèi)存，所有實(shí)例大小98M內(nèi)存，且所有的RaftServerMetrics實(shí)例被一個ConcurrentHashMap引用。
然后右鍵RaftServerMetrics->Merge shortest path to GC Roots ->with all references查找所有引用RaftServerMetrics的地方，結(jié)果如下，可看到所有的RaftServerMetrics實(shí)例被變量metricsMap引用，問題原因是RaftServerMetrics使用完后，未從靜態(tài)變量metricsMap里刪除。
MemoryAnalyzer自動分析內(nèi)存泄露時，有時并不能準(zhǔn)確的找到，此時需要自己分析哪些對象占用內(nèi)存過多。下圖是使用jvisualvm.exe打開堆的結(jié)果，查看數(shù)目或者內(nèi)存異常的對象，可以看到很多對象數(shù)目都是111580個，且最后一列顯示的內(nèi)存占用大，從對象的包分析，都和netty有關(guān)，且是client相關(guān)的對象，基本確認(rèn)這些對象和內(nèi)存泄露有關(guān)。進(jìn)一步分析代碼，發(fā)現(xiàn)大量RPC連接使用完后未關(guān)閉。
JDK提供繞過JVM直接在操作系統(tǒng)申請內(nèi)存的接口，例如通過Unsafe類的allocateMemory、freeMemory直接分配、釋放內(nèi)存，內(nèi)存對象的引用在堆上，但內(nèi)存在堆外。排查此類內(nèi)存泄露，首先開啟：
-XX:NativeMemoryTracking=detail
然后jcmd pid VM.native_memory detail，打出內(nèi)存分配信息，注意NativeMemoryTracking顯示的內(nèi)存不包含C++分配的內(nèi)存。此處需要關(guān)注兩個點(diǎn)，第一，Total行的committed數(shù)值是否等于進(jìn)程占用的物理內(nèi)存，如果不等，說明有C++等native code分配的內(nèi)存，可參考Java調(diào)用C++組件 分析；第二，Native Memory Tracking的committed數(shù)值是否過大，如果過大，說明有Unsafe.allocateMemory分配了太多內(nèi)存。
Unsafe.allocateMemory的使用場景有兩個：第一，封裝在DirectByteBuffer內(nèi)；第二，業(yè)務(wù)直接使用Unsafe.allocateMemory。
DirectByteBuff通常被用于通信框架如netty中，不僅可以減少GC壓力，而且避免IO操作時將對象從堆上拷貝到堆外。為了快速驗(yàn)證是否DirectByteBuffer導(dǎo)致內(nèi)存泄露，可使用參數(shù)-XX:MaxDirectMemorySize限制DirectByteBuffer分配的堆外內(nèi)存大小，如果堆外內(nèi)存仍然大于MaxDirectMemorySize，可基本排除DirectByteBuffer導(dǎo)致的內(nèi)存泄露。
分析DirectByteBuffer的內(nèi)存首先可用Java Mission Control，綁定到進(jìn)程，并查看DirectByteBuffer占的內(nèi)存如2.24GB。此處也可直接用MemoryAnalyzer打開dump的堆，統(tǒng)計所有DirectByteBuffer的capacity之和，計算DirectByteBuffer申請的堆外內(nèi)存大小。
然后用命令jdk/bin/jmap -dump:live,format=b,file=heap.hprof {pid}，導(dǎo)出堆里所有活著的對象，并用MemoryAnalyzer打開dump的堆，分析所有的DirectByteBuffe：Merge shortest path to GC Roots ->with all references。
如果排除DirectByteBuffer，那就是應(yīng)用程序直接用Unsafe類的allocateMemory分配的內(nèi)存，例如Spark的off heap memory[1]。此時可排查代碼所有Unsafe.allocateMemory的地方。
例如RocksDB采用C++實(shí)現(xiàn)，并通過JNI提供給Java調(diào)用的接口，如果Java通過JNI創(chuàng)建了新的RocksDB實(shí)例，RocksDB會啟動若干后臺線程申請、釋放內(nèi)存，這部分內(nèi)存都對Java不可見，如果發(fā)生泄漏，也無法通過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
然后在進(jìn)程啟動腳本里，添加如下命令，LD_PRELOAD表示JVM申請內(nèi)存時不再用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
并在進(jìn)程的啟動命令里添加參數(shù)-XX:+PreserveFramePointer。進(jìn)程啟動后，隨著不斷申請內(nèi)存，會生成很多dump文件，可把所有dump文件通過命令一起分析：jeprof --show_bytes --pdf jdk/bin/java *.heap > leak.pdf。
leak.pdf如下所示，可看到所有申請內(nèi)存的路徑，進(jìn)程共申請過88G內(nèi)存，而RocksDB申請了74.2%的內(nèi)存，基本確定是不正常的行為，排查發(fā)現(xiàn)不斷創(chuàng)建新的RocksDB實(shí)例，共1024個，每個實(shí)例都在運(yùn)行，優(yōu)化方法是合并RocksDB實(shí)例。
需要注意的是，88G是所有申請過的內(nèi)存，包含申請但已經(jīng)被釋放的，因此通過該方法，大部分情況下能確定泄露源頭，但并不十分準(zhǔn)確，準(zhǔn)確的方法是在C++代碼里用鉤子函數(shù)勾住malloc和free，記錄哪些內(nèi)存未被釋放。
perf是最為普遍的性能分析工具，在Java里可采用阿里的工具arthas進(jìn)行perf，并生成火焰圖，該工具可在docker容器內(nèi)使用，而系統(tǒng)perf命令在容器里使用有諸多限制。
下載arthas-bin.zip[2]，運(yùn)行./a.sh，然后綁定到對應(yīng)的進(jìn)程，開始perf: profiler start，采樣一段時間后，停止perf: profiler stop。結(jié)果如下所示，可看到getServiceList耗了63.75%的CPU。
另外，常用優(yōu)化小建議：熱點(diǎn)函數(shù)避免使用lambda表達(dá)式如stream.collect等、熱點(diǎn)函數(shù)避免使用正則表達(dá)式、避免把UUID轉(zhuǎn)成String在協(xié)議里傳輸?shù)取?/p>
perf適用于查找整個程序的熱點(diǎn)函數(shù)，但不適用于分析單次RPC調(diào)用的耗時分布，此時就需要jaeger。
jaeger是Uber開源的一個基于Go的分布式追蹤系統(tǒng)。jaeger基本原理是：用戶在自己代碼里插樁，并上報給jaeger，jaeger匯總流程并在UI顯示。非生產(chǎn)環(huán)境可安裝jaeger-all-in-one[3]，數(shù)據(jù)都在內(nèi)存里，有內(nèi)存溢出的風(fēng)險。在需要追蹤的服務(wù)的啟動腳本里export JAEGER_AGENT_HOST={jaeger服務(wù)所在的host}。
下圖為jaeger的UI，顯示一次完整的流程，左邊為具體的插樁名稱，右邊為每塊插裝代碼耗時，可以看到最耗時的部分在including leader create container和including follower create container，這部分語義是leader創(chuàng)建完container后，兩個follower才開始創(chuàng)建container，而創(chuàng)建container非常耗時，如果改成leader和兩個follower同時創(chuàng)建container，則時間減少一半。
tcpdump常用來抓包分析，但也能用來優(yōu)化性能。在我們的場景中，部署Ozone集群（下一代分布式對象存儲系統(tǒng)），并讀數(shù)據(jù)，結(jié)果發(fā)現(xiàn)文件越大讀速越慢，讀1G文件，速度只有2.2M每秒，使用perf未發(fā)現(xià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請求導(dǎo)出到read.cap文件，然后用wireshark打開read.cap，并過濾出HTTP協(xié)議，因?yàn)榇蟛糠謪f(xié)議都是TCP協(xié)議，用于傳輸數(shù)據(jù)，而HTTP協(xié)議用于請求開始和結(jié)束。
從下圖的wireshark界面，可看到讀200M文件，共有10個GET請求：GET /goofys-bucket/test.dbf HTTP/1.1，每個GET請求讀20M文件，每個GET請求讀完后回復(fù)：HTTP/1.1 200 OK。第1個GET請求到達(dá)S3gateway時間為0.2287秒，第10個GET請求到達(dá)Ozone集群時間為1.026458秒。第1個GET請求完成時間為1.869579秒，第10個GET請求完成時間為23.640925秒。
可見10個GET請求在1秒內(nèi)全部到達(dá)Ozone集群，但每個請求耗時越來越長。因此只需要分析后續(xù)的GET請求讀同樣大小的數(shù)據(jù)塊，比前序GET請求多做了哪些事情即可。
最后通過分析日志和閱讀代碼發(fā)現(xiàn)，Ozone采用的第三方庫commons-io采用read實(shí)現(xiàn)skip。例如讀第10個GET請求時，實(shí)際只需要讀[180M, 200M)，但commons-io實(shí)現(xiàn)skip前180M時，會將前180M讀出來，導(dǎo)致第10個GET請求讀完整的[0M, 200M)，因此GET請求越來越慢。優(yōu)化后，性能提升一百倍。
jstack用來查詢線程狀態(tài)，但在極端情況下也可以用于性能優(yōu)化。在部署服務(wù)時，發(fā)現(xiàn)進(jìn)程迅速占滿所有CPU，24核的機(jī)器進(jìn)程使用CPU達(dá)到2381%。
CPU使用如此之高，無法運(yùn)行arthas進(jìn)行perf分析，只能采用其他策略。首先用top -Hp pid命令打出進(jìn)程pid的所有線程及每個線程的CPU消耗。如下圖，第一列PID為線程號，%CPU列代表CPU消耗，注意該圖只是展示作用，該圖的進(jìn)程并不是使用CPU達(dá)到2381%的進(jìn)程，原進(jìn)程的信息當(dāng)初沒保存。
然后計算出使用CPU最高的線程號的十六進(jìn)制表示0x417，再用jstack -l pid > jstack.txt命令打出所有線程狀態(tài)，用0x417在jstack.txt查詢消耗CPU最高的線程，即下圖所示ThreadPoolExecutor里的線程，該線程一直處于RUNNABLE，且隊(duì)列為empty，基本確認(rèn)該部分線程出了問題，因?yàn)檎５木€程不會一直空轉(zhuǎn)，狀態(tài)會有TIMED_WAITING的時刻。
因?yàn)榫€程堆棧不包含業(yè)務(wù)代碼，都是JDK的源碼，因此用線程堆棧搜索JDK相關(guān)問題，最終發(fā)現(xiàn)是JDK8的Bug：JDK-8129861，該Bug在創(chuàng)建大小為0的線程池時容易觸發(fā)，因此在應(yīng)用代碼里，將大小為0的線程池修改即可。
在生產(chǎn)環(huán)境發(fā)生過進(jìn)程被清理腳本殺掉。排查工具有兩個：linux自帶的auditd和systemtap。
首先使用auditd，因?yàn)樵摴ぞ吆唵我子?，不用安裝。使用service auditd status檢查服務(wù)狀態(tài)，如果未啟動可用service auditd restart啟動。然后使用命令：auditctl -a exit,always -F arch=b64 -S kill，監(jiān)聽所有的Kill信號。如下圖所示，從type=OBJ_PID行里可以看到：捕捉到的Kill信號殺的進(jìn)程號opid=40442，線程名ocomm=”rocksdb:pst_st”，注意這里打出的線程名而不是進(jìn)程名。
從type=SYSCALL行里可以看到：a1=9表示kill -9；發(fā)出kill -9的進(jìn)程是exe=”/usr/bin/bash”，進(jìn)程號是pid=98003。從這些信息并不能找到相應(yīng)的進(jìn)程，因?yàn)槟_本往往運(yùn)行完就停止，生命周期非常短。
接下來使用systemtap分析，systemtap需要安裝：yum install systemtap systemtap-runtime。先寫systemtap腳本findkiller.stp，如下所示，該systemtap腳本捕捉殺進(jìn)程sig_pid的KILL信號，并使用task_ancestry打印發(fā)出KILL信號進(jìn)程的所有祖先進(jìn)程。
重慶分公司
重慶分公司
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，有的機(jī)器需要將ko文件補(bǔ)上簽名才能運(yùn)行。然后運(yùn)行：nohup staprun -x 98120 stap_XX.ko >nohup.out 2>&1 &，此處的98120即為腳本中的target()。
捕捉結(jié)果如下，從圖里可以看出發(fā)出KILL命令的進(jìn)程是通過crond啟動的，也就是說定時任務(wù)運(yùn)行了某些腳本殺了進(jìn)程。但仍然不知道定時任務(wù)啟動了哪個腳本殺了進(jìn)程。
接下來再用auditd排查，使用命令：auditctl -a exit,always -F arch=b64 -S execve捕捉所有的系統(tǒng)調(diào)用，結(jié)果如下，最后一行是捕捉到殺進(jìn)程opid=20286的信號，從圖中可看出kill信號附近出現(xiàn)的都是/data/tools/clean命令。
/data/tools/clean里調(diào)用了若干腳本，在每個腳本里用打出當(dāng)前腳本名和進(jìn)程號到crontab.pid里。并和systemtap抓到的進(jìn)程號62118對比，找到了KILL信號是從kill_non_run_app.sh腳本里發(fā)出。
如果在Java程序里顯式調(diào)用System.exit結(jié)束進(jìn)程，可以用arthas排查。首先寫腳本system_exit.as如下。
options unsafe truestack java.lang.System exit -n 1
運(yùn)行命令nohup ./as.sh -f system_exit.as 69001 -b > system_exit.out 2>&1 &，即可監(jiān)控進(jìn)程69001調(diào)用的所有System.exit。
此處發(fā)生的Crash案例和下文Java內(nèi)Crash產(chǎn)生的原因一樣，但現(xiàn)象不一樣，大部分情況下，是Crash在C++代碼，只產(chǎn)生core文件，不產(chǎn)生Java內(nèi)Crash的Crash log；少量情況下Crash在JVM里，產(chǎn)生Java內(nèi)Crash的Crash log。
如果Java通過JNI調(diào)用C++代碼，在C++里發(fā)生Crash，JVM有時不會產(chǎn)生任何信息就退出，此時借助操作系統(tǒng)產(chǎn)生的core file分析進(jìn)程退出原因，但操作系統(tǒng)默認(rèn)關(guān)閉該功能，如下圖所示core file size為0表示關(guān)閉該功能。
因此需要在進(jìn)程的啟動腳本里（只影響當(dāng)前進(jìn)程）設(shè)置ulimit -c ulimited來設(shè)置core file的大小，啟動進(jìn)程后，打開/proc/{pid}/limits，查看Max core file size的大小確認(rèn)是否開啟。
當(dāng)發(fā)生Crash時，會生成core.pid文件，一般core.pid文件會非常大，因?yàn)樵撐募怂刑摂M內(nèi)存大小，所以大于物理內(nèi)存，如下圖所示core.44729共53GB。
接下來使用命令gdb bin/java core.44729打開core文件，發(fā)現(xiàn)是rocksdb start thread時掛的，掛在libstdc++里，這是glibc庫，基本不可能出問題，因此該堆?？赡苁潜硐?，有其他原因?qū)е聅tart thread失敗。
注意到打開core文件時，有太多線程-LWP輕量級進(jìn)程。
然后在gdb里用info threads，發(fā)現(xiàn)有三萬多個線程，都在wait鎖狀態(tài)，基本確認(rèn)三萬多個線程，導(dǎo)致內(nèi)存太大，創(chuàng)建不出來新的線程，因此掛在start thread里。
接著分析三萬多個線程都是什么線程，隨機(jī)選幾十個線程，打出每個線程的堆棧，可以看到大部分線程都是jvm線程。因?yàn)閞ocksdb創(chuàng)建出來的線程是：
從/tmp/librocksdbjni8646115773822033422.so來的；而jvm創(chuàng)建出來的線程都是從/usr/java/jdk1.8.0_191-amd64/jre/lib/amd64/server/libjvm.so來的，這部分線程占了大部分。
排查Java內(nèi)Crash的原因如OOM等，需要配置JVM的如下參數(shù)：
-XX:ErrorFile-XX:+HeapDumpOnOutOfMemoryError-XX:HeapDumpPath。JVM內(nèi)發(fā)生Crash時，會在-XX:ErrorFile配置的路徑下生成crash log。而-XX:+HeapDumpOnOutOfMemoryError、-XX:HeapDumpPath用于發(fā)生OOM時生成Dump堆，用于還原現(xiàn)場。下圖所示為產(chǎn)生的crash log?？梢钥吹絼?chuàng)建線程時發(fā)生OutOfMemory導(dǎo)致進(jìn)程掛掉。
從下圖crash log可以看到有兩萬四千個Datanode State Machine Thread線程都在等鎖。到此確認(rèn)上文Java調(diào)用C++發(fā)生Crash 產(chǎn)生core.pid的進(jìn)程和產(chǎn)生crash log的進(jìn)程都是因?yàn)閮扇f多個Datanode State Machine Thread掛掉。
接著分析為何有兩萬多個Datanode State Machine Thread，代碼里可以看到該線程用線程池newCacheThreadPool創(chuàng)建。該newCacheThreadPool在沒有線程可用，例如線程都在等鎖的情況下，會創(chuàng)建新的線程，因此創(chuàng)建了兩萬多個線程。接著分析Datanode State Machine Thread等的什么鎖。在進(jìn)程的線程數(shù)超過5000時，用jstack -l pid > jstack.txt打出所有線程的狀態(tài)。
可以看到幾乎所有Datanode State Machine Thread在等鎖，而只有一個Datanode State Machine Thread – 5500 拿到了鎖，但是卡在提交RPC請求submitRequest。至此Java調(diào)用C++發(fā)生Crash 和Java內(nèi)Crash的原因找到。
jstack打出的死鎖信息如下所示。grpc-default-executor-14765線程拿到了log4j的鎖，在等RaftServerImpl的鎖；grpc-default-executor-14776線程拿到了RaftServerImpl的鎖，在等log4j的鎖，導(dǎo)致這兩個線程都拿到了對方等待的鎖，所以造成兩個線程死鎖。可以看出，僅僅打日志的log4j，不釋放鎖是最值得懷疑的地方。最后發(fā)現(xiàn)log4j存在死鎖的缺陷[4]。該缺陷在log4j2得到解決，升級log4j即可。
jstack打出的死鎖信息如下所示。grpc-default-executor-3449線程拿到了RaftLog的鎖，在等DataBlockingQueue的鎖；SegmentedRaftLogWorker拿到了DataBlockingQueue的鎖，在等RaftLog的鎖。
這里最值得懷疑的是SegmentedRaftLogWorker拿到了DataBlockingQueue的鎖卻不釋放，因?yàn)閝ueue的操作只是在隊(duì)列里增、刪、查元素。如下圖所示DataBlockingQueue的方法poll，使用的鎖是自己封裝的鎖AutoCloseableLock implement AutoCloseable,鎖的釋放依賴于AutoCloseableLock重載的close方法。
再看acquire方法，先用lock.lock()拿到鎖，再創(chuàng)建新的AutoCloseableLock對象，如果拿到鎖后，在創(chuàng)建新對象AutoCloseableLock時發(fā)生OOM等異常，鎖就無法釋放。
以上是“Java中內(nèi)存泄漏、性能優(yōu)化、宕機(jī)死鎖的示例分析”這篇文章的所有內(nèi)容，感謝各位的閱讀！相信大家都有了一定的了解，希望分享的內(nèi)容對大家有所幫助，如果還想學(xué)習(xí)更多知識，歡迎關(guān)注創(chuàng)新互聯(lián)-成都網(wǎng)站建設(shè)公司行業(yè)資訊頻道！
