導(dǎo)讀

本文介紹Java諸多優(yōu)化實(shí)例：第一，排查堆上、堆外內(nèi)存泄露；第二，使用arthas、jaeger、tcpdump、jstack做性能優(yōu)化；第三，排查進(jìn)程異常退出的原因，如被殺、System.exit、Java調(diào)用的C++發(fā)生Crash、Java內(nèi)Crash；第四，排查死鎖的原因，如log4j死鎖、封裝不嚴(yán)謹(jǐn)導(dǎo)致的死鎖

內(nèi)存泄漏

內(nèi)存泄露在C++里排查很簡(jiǎn)單，用鉤子函數(shù)勾住內(nèi)存分配和釋放函數(shù)malloc和free，統(tǒng)計(jì)哪些malloc的內(nèi)存沒(méi)有free，就可以找出內(nèi)存泄露的源頭。但在Java里問(wèn)題復(fù)雜的多，主要因?yàn)镴ava在內(nèi)存之上有層JVM管理內(nèi)存。

JVM先從操作系統(tǒng)申請(qǐ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)是堆上泄漏還是堆外泄露。可以通過(guò)jmap -heap pid確認(rèn)，如下圖所示，老年代PS Old Generation使用率占99.99%，再結(jié)合gc log，如果老年代回收不掉，基本確認(rèn)為堆上內(nèi)存泄露，也不排除進(jìn)程本身需要這么多內(nèi)存，此時(shí)需要分析堆。而堆外內(nèi)存泄露的顯著表現(xiàn)是top命令查出來(lái)的物理內(nèi)存顯著比通過(guò)xmx配置的最大內(nèi)存大。

堆上內(nèi)存泄漏

堆上內(nèi)存泄露是最常見的，申請(qǐng)的對(duì)象引用和內(nèi)存全在JVM堆上，而對(duì)象使用完后，對(duì)象引用被其他長(zhǎng)生命周期的對(duì)象一直拿著，導(dǎo)致無(wú)法從堆上釋放。首先用jdk/bin/jmap -dump:live,format=b,file=heap.hprof {pid}，導(dǎo)出堆里所有活著的對(duì)象。然后用工具分析heap.hprof。

分析堆上內(nèi)存泄露的主流工具有兩種：JDK自帶的bin目錄下的jvisualvm.exe、Eclipse的MemoryAnalyzer。MemoryAnalyzer更強(qiáng)大，可自動(dòng)分析可疑的內(nèi)存泄露。使用MemoryAnalyzer時(shí)，需要在MemoryAnalyzer.ini里通過(guò)-Xmx參數(shù)配置最大內(nèi)存，否則無(wú)法打開大堆。接下來(lái)介紹堆上內(nèi)存泄露的若干實(shí)例。

對(duì)象被靜態(tài)對(duì)象引用

使用MemoryAnalyzer自動(dòng)分析內(nèi)存泄露，報(bào)告如下，可以看到RaftServerMetrics占了44.68%的內(nèi)存，所有實(shí)例大小98M內(nèi)存，且所有的RaftServerMetrics實(shí)例被一個(gè)ConcurrentHashMap引用。

接著在直方圖里過(guò)濾RaftServerMetrics，共找到2065個(gè)實(shí)例。

然后右鍵RaftServerMetrics->Merge shortest path to GC Roots ->with all references查找所有引用RaftServerMetrics的地方，結(jié)果如下，可看到所有的RaftServerMetrics實(shí)例被變量metricsMap引用，問(wèn)題原因是RaftServerMetrics使用完后，未從靜態(tài)變量metricsMap里刪除。

RPC連接使用完后未關(guān)閉

MemoryAnalyzer自動(dòng)分析內(nèi)存泄露時(shí)，有時(shí)并不能準(zhǔn)確的找到，此時(shí)需要自己分析哪些對(duì)象占用內(nèi)存過(guò)多。下圖是使用jvisualvm.exe打開堆的結(jié)果，查看數(shù)目或者內(nèi)存異常的對(duì)象，可以看到很多對(duì)象數(shù)目都是111580個(gè)，且最后一列顯示的內(nèi)存占用大，從對(duì)象的包分析，都和netty有關(guān)，且是client相關(guān)的對(duì)象，基本確認(rèn)這些對(duì)象和內(nèi)存泄露有關(guān)。進(jìn)一步分析代碼，發(fā)現(xiàn)大量RPC連接使用完后未關(guān)閉。

堆外內(nèi)存泄露

Java使用堆外內(nèi)存

JDK提供繞過(guò)JVM直接在操作系統(tǒng)申請(qǐng)內(nèi)存的接口，例如通過(guò)Unsafe類的allocateMemory、freeMemory直接分配、釋放內(nèi)存，內(nèi)存對(duì)象的引用在堆上，但內(nèi)存在堆外。排查此類內(nèi)存泄露，首先開啟：

-XX:NativeMemoryTracking=detail

然后jcmd pid VM.native_memory detail，打出內(nèi)存分配信息，注意NativeMemoryTracking顯示的內(nèi)存不包含C++分配的內(nèi)存。此處需要關(guān)注兩個(gè)點(diǎn)，第一，Total行的committed數(shù)值是否等于進(jìn)程占用的物理內(nèi)存，如果不等，說(shuō)明有C++等native code分配的內(nèi)存，可參考Java調(diào)用C++組件?分析；第二，Native Memory Tracking的committed數(shù)值是否過(guò)大，如果過(guò)大，說(shuō)明有Unsafe.allocateMemory分配了太多內(nèi)存。

Unsafe.allocateMemory的使用場(chǎng)景有兩個(gè)：第一，封裝在DirectByteBuffer內(nèi)；第二，業(yè)務(wù)直接使用Unsafe.allocateMemory。

DirectByteBuff通常被用于通信框架如netty中，不僅可以減少GC壓力，而且避免IO操作時(shí)將對(duì)象從堆上拷貝到堆外。為了快速驗(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)計(jì)所有DirectByteBuffer的capacity之和，計(jì)算DirectByteBuffer申請(qǐng)的堆外內(nèi)存大小。

然后用命令jdk/bin/jmap -dump:live,format=b,file=heap.hprof {pid}，導(dǎo)出堆里所有活著的對(duì)象，并用MemoryAnalyzer打開dump的堆，分析所有的DirectByteBuffe：Merge shortest path to GC Roots ->with all references。

如果排除DirectByteBuffer，那就是應(yīng)用程序直接用Unsafe類的allocateMemory分配的內(nèi)存，例如Spark的off heap memory[1]。此時(shí)可排查代碼所有Unsafe.allocateMemory的地方。

Java調(diào)用C++組件

例如RocksDB采用C++實(shí)現(xiàn)，并通過(guò)JNI提供給Java調(diào)用的接口，如果Java通過(guò)JNI創(chuàng)建了新的RocksDB實(shí)例，RocksDB會(huì)啟動(dòng)若干后臺(tái)線程申請(qǐng)、釋放內(nèi)存，這部分內(nèi)存都對(duì)Java不可見，如果發(fā)生泄漏，也無(wú)法通過(guò)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)程啟動(dòng)腳本里，添加如下命令，LD_PRELOAD表示JVM申請(qǐng)內(nèi)存時(shí)不再用glibc的ptmalloc，而是使用jemalloc。MALLOC_CONF的lg_prof_interval表示每次申請(qǐng)2^30Byte時(shí)生成一個(gè)heap文件。export LD_PRELOAD=/usr/local/lib/libjemalloc.soexport MALLOC_CONF=prof:true,lg_prof_interval:30

并在進(jìn)程的啟動(dòng)命令里添加參數(shù)-XX:+PreserveFramePointer。進(jìn)程啟動(dòng)后，隨著不斷申請(qǐng)內(nèi)存，會(huì)生成很多dump文件，可把所有dump文件通過(guò)命令一起分析：jeprof --show_bytes --pdf jdk/bin/java *.heap > leak.pdf。

leak.pdf如下所示，可看到所有申請(qǐng)內(nèi)存的路徑，進(jìn)程共申請(qǐng)過(guò)88G內(nèi)存，而RocksDB申請(qǐng)了74.2%的內(nèi)存，基本確定是不正常的行為，排查發(fā)現(xiàn)不斷創(chuàng)建新的RocksDB實(shí)例，共1024個(gè)，每個(gè)實(shí)例都在運(yùn)行，優(yōu)化方法是合并RocksDB實(shí)例。

需要注意的是，88G是所有申請(qǐng)過(guò)的內(nèi)存，包含申請(qǐng)但已經(jīng)被釋放的，因此通過(guò)該方法，大部分情況下能確定泄露源頭，但并不十分準(zhǔn)確，準(zhǔn)確的方法是在C++代碼里用鉤子函數(shù)勾住malloc和free，記錄哪些內(nèi)存未被釋放。

性能優(yōu)化

arthas

perf是最為普遍的性能分析工具，在Java里可采用阿里的工具arthas進(jìn)行perf，并生成火焰圖，該工具可在docker容器內(nèi)使用，而系統(tǒng)perf命令在容器里使用有諸多限制。

下載arthas-bin.zip[2]，運(yùn)行./a.sh，然后綁定到對(duì)應(yīng)的進(jìn)程，開始perf: profiler start，采樣一段時(shí)間后，停止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ù)取?br />

jaeger

perf適用于查找整個(gè)程序的熱點(diǎn)函數(shù)，但不適用于分析單次RPC調(diào)用的耗時(shí)分布，此時(shí)就需要jaeger。

?jaeger是Uber開源的一個(gè)基于Go的分布式追蹤系統(tǒng)。jaeger基本原理是：用戶在自己代碼里插樁，并上報(bào)給jaeger，jaeger匯總流程并在UI顯示。非生產(chǎn)環(huán)境可安裝jaeger-all-in-one[3]，數(shù)據(jù)都在內(nèi)存里，有內(nèi)存溢出的風(fēng)險(xiǎn)。在需要追蹤的服務(wù)的啟動(dòng)腳本里export JAEGER_AGENT_HOST={jaeger服務(wù)所在的host}。

下圖為jaeger的UI，顯示一次完整的流程，左邊為具體的插樁名稱，右邊為每塊插裝代碼耗時(shí)，可以看到最耗時(shí)的部分在including leader create container和including follower create container，這部分語(yǔ)義是leader創(chuàng)建完container后，兩個(gè)follower才開始創(chuàng)建container，而創(chuàng)建container非常耗時(shí)，如果改成leader和兩個(gè)follower同時(shí)創(chuàng)建container，則時(shí)間減少一半。

tcpdump

tcpdump常用來(lái)抓包分析，但也能用來(lái)優(yōu)化性能。在我們的場(chǎng)景中，部署Ozone集群（下一代分布式對(duì)象存儲(chǔ)系統(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文件時(shí)會(huì)將所有GET請(qǐng)求導(dǎo)出到read.cap文件，然后用wireshark打開read.cap，并過(guò)濾出HTTP協(xié)議，因?yàn)榇蟛糠謪f(xié)議都是TCP協(xié)議，用于傳輸數(shù)據(jù)，而HTTP協(xié)議用于請(qǐng)求開始和結(jié)束。

從下圖的wireshark界面，可看到讀200M文件，共有10個(gè)GET請(qǐng)求：GET /goofys-bucket/test.dbf HTTP/1.1，每個(gè)GET請(qǐng)求讀20M文件，每個(gè)GET請(qǐng)求讀完后回復(fù)：HTTP/1.1 200 OK。第1個(gè)GET請(qǐng)求到達(dá)S3gateway時(shí)間為0.2287秒，第10個(gè)GET請(qǐng)求到達(dá)Ozone集群時(shí)間為1.026458秒。第1個(gè)GET請(qǐng)求完成時(shí)間為1.869579秒，第10個(gè)GET請(qǐng)求完成時(shí)間為23.640925秒。

可見10個(gè)GET請(qǐng)求在1秒內(nèi)全部到達(dá)Ozone集群，但每個(gè)請(qǐng)求耗時(shí)越來(lái)越長(zhǎng)。因此只需要分析后續(xù)的GET請(qǐng)求讀同樣大小的數(shù)據(jù)塊，比前序GET請(qǐng)求多做了哪些事情即可。

最后通過(guò)分析日志和閱讀代碼發(fā)現(xiàn)，Ozone采用的第三方庫(kù)commons-io采用read實(shí)現(xiàn)skip。例如讀第10個(gè)GET請(qǐng)求時(shí)，實(shí)際只需要讀[180M, 200M)，但commons-io實(shí)現(xiàn)skip前180M時(shí)，會(huì)將前180M讀出來(lái)，導(dǎo)致第10個(gè)GET請(qǐng)求讀完整的[0M, 200M)，因此GET請(qǐng)求越來(lái)越慢。優(yōu)化后，性能提升一百倍。

jstack

jstack用來(lái)查詢線程狀態(tài)，但在極端情況下也可以用于性能優(yōu)化。在部署服務(wù)時(shí)，發(fā)現(xiàn)進(jìn)程迅速占滿所有CPU，24核的機(jī)器進(jìn)程使用CPU達(dá)到2381%。

CPU使用如此之高，無(wú)法運(yùn)行arthas進(jìn)行perf分析，只能采用其他策略。首先用top -Hp pid命令打出進(jìn)程pid的所有線程及每個(gè)線程的CPU消耗。如下圖，第一列PID為線程號(hào)，%CPU列代表CPU消耗，注意該圖只是展示作用，該圖的進(jìn)程并不是使用CPU達(dá)到2381%的進(jìn)程，原進(jìn)程的信息當(dāng)初沒(méi)保存。

然后計(jì)算出使用CPU最高的線程號(hào)的十六進(jìn)制表示0x417，再用jstack -l pid > jstack.txt命令打出所有線程狀態(tài)，用0x417在jstack.txt查詢消耗CPU最高的線程，即下圖所示ThreadPoolExecutor里的線程，該線程一直處于RUNNABLE，且隊(duì)列為empty，基本確認(rèn)該部分線程出了問(wèn)題，因?yàn)檎５木€程不會(huì)一直空轉(zhuǎn)，狀態(tài)會(huì)有TIMED_WAITING的時(shí)刻。

因?yàn)榫€程堆棧不包含業(yè)務(wù)代碼，都是JDK的源碼，因此用線程堆棧搜索JDK相關(guān)問(wèn)題，最終發(fā)現(xiàn)是JDK8的Bug：JDK-8129861，該Bug在創(chuàng)建大小為0的線程池時(shí)容易觸發(fā)，因此在應(yīng)用代碼里，將大小為0的線程池修改即可。

宕機(jī)

被其他進(jìn)程殺

在生產(chǎn)環(huán)境發(fā)生過(guò)進(jìn)程被清理腳本殺掉。排查工具有兩個(gè)：linux自帶的auditd和systemtap。

首先使用auditd，因?yàn)樵摴ぞ吆?jiǎn)單易用，不用安裝。使用service auditd status檢查服務(wù)狀態(tài)，如果未啟動(dòng)可用service auditd restart啟動(dòng)。然后使用命令：auditctl -a exit,always -F arch=b64 -S kill，監(jiān)聽所有的Kill信號(hào)。如下圖所示，從type=OBJ_PID行里可以看到：捕捉到的Kill信號(hào)殺的進(jìn)程號(hào)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)程號(hào)是pid=98003。從這些信息并不能找到相應(yīng)的進(jìn)程，因?yàn)槟_本往往運(yùn)行完就停止，生命周期非常短。

接下來(lái)使用systemtap分析，systemtap需要安裝：yum install systemtap systemtap-runtime。先寫systemtap腳本findkiller.stp，如下所示，該systemtap腳本捕捉殺進(jìn)程sig_pid的KILL信號(hào)，并使用task_ancestry打印發(fā)出KILL信號(hào)進(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)程是通過(guò)crond啟動(dòng)的，也就是說(shuō)定時(shí)任務(wù)運(yùn)行了某些腳本殺了進(jìn)程。但仍然不知道定時(shí)任務(wù)啟動(dòng)了哪個(gè)腳本殺了進(jìn)程。

接下來(lái)再用auditd排查，使用命令：auditctl -a exit,always -F arch=b64 -S execve捕捉所有的系統(tǒng)調(diào)用，結(jié)果如下，最后一行是捕捉到殺進(jìn)程opid=20286的信號(hào)，從圖中可看出kill信號(hào)附近出現(xiàn)的都是/data/tools/clean命令。

/data/tools/clean里調(diào)用了若干腳本，在每個(gè)腳本里用打出當(dāng)前腳本名和進(jìn)程號(hào)到crontab.pid里。并和systemtap抓到的進(jìn)程號(hào)62118對(duì)比，找到了KILL信號(hào)是從kill_non_run_app.sh腳本里發(fā)出。

調(diào)用System的exit

如果在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。

Java調(diào)用的C++發(fā)生Crash

此處發(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通過(guò)JNI調(diào)用C++代碼，在C++里發(fā)生Crash，JVM有時(shí)不會(huì)產(chǎn)生任何信息就退出，此時(shí)借助操作系統(tǒng)產(chǎn)生的core file分析進(jìn)程退出原因，但操作系統(tǒng)默認(rèn)關(guān)閉該功能，如下圖所示core file size為0表示關(guān)閉該功能。

因此需要在進(jìn)程的啟動(dòng)腳本里（只影響當(dāng)前進(jìn)程）設(shè)置ulimit -c ulimited來(lái)設(shè)置core file的大小，啟動(dòng)進(jìn)程后，打開/proc/{pid}/limits，查看Max core file size的大小確認(rèn)是否開啟。

當(dāng)發(fā)生Crash時(shí)，會(huì)生成core.pid文件，一般core.pid文件會(huì)非常大，因?yàn)樵撐募怂刑摂M內(nèi)存大小，所以大于物理內(nèi)存，如下圖所示core.44729共53GB。

接下來(lái)使用命令gdb bin/java core.44729打開core文件，發(fā)現(xiàn)是rocksdb start thread時(shí)掛的，掛在libstdc++里，這是glibc庫(kù)，基本不可能出問(wèn)題，因此該堆棧可能是表象，有其他原因?qū)е聅tart thread失敗。

注意到打開core文件時(shí)，有太多線程-LWP輕量級(jí)進(jìn)程。

然后在gdb里用info threads，發(fā)現(xiàn)有三萬(wàn)多個(gè)線程，都在wait鎖狀態(tài)，基本確認(rèn)三萬(wàn)多個(gè)線程，導(dǎo)致內(nèi)存太大，創(chuàng)建不出來(lái)新的線程，因此掛在start thread里。

接著分析三萬(wàn)多個(gè)線程都是什么線程，隨機(jī)選幾十個(gè)線程，打出每個(gè)線程的堆棧，可以看到大部分線程都是jvm線程。因?yàn)閞ocksdb創(chuàng)建出來(lái)的線程是：

從/tmp/librocksdbjni8646115773822033422.so來(lái)的；而jvm創(chuàng)建出來(lái)的線程都是從/usr/java/jdk1.8.0_191-amd64/jre/lib/amd64/server/libjvm.so來(lái)的，這部分線程占了大部分。

因此問(wèn)題出在Java代碼里，產(chǎn)生core.pid文件的進(jìn)程，雖然沒(méi)有產(chǎn)生crash log，但也是因?yàn)镴ava 線程太多，導(dǎo)致C++代碼創(chuàng)建線程時(shí)掛掉。至于為什么Java線程太多請(qǐng)看Java內(nèi)Crash。
另外，core.pid完整的保留了C++組件Crash時(shí)的現(xiàn)場(chǎng)，包括變量、寄存器的值等，如果真的因?yàn)镃++組件有Bug而Crash，例如空指針等。首先自行找到C++源碼，找出懷疑空指針的變量{variableName}，通過(guò)在gdb里執(zhí)行命令:p {variableName}，可以看出每個(gè)變量的值，從而找出空指針的變量。

Java內(nèi)Crash

排查Java內(nèi)Crash的原因如OOM等，需要配置JVM的如下參數(shù)：

-XX:ErrorFile

-XX:+HeapDumpOnOutOfMemoryError

-XX:HeapDumpPath。

JVM內(nèi)發(fā)生Crash時(shí)，會(huì)在-XX:ErrorFile配置的路徑下生成crash log。而-XX:+HeapDumpOnOutOfMemoryError、-XX:HeapDumpPath用于發(fā)生OOM時(shí)生成Dump堆，用于還原現(xiàn)場(chǎng)。下圖所示為產(chǎn)生的crash log。可以看到創(chuàng)建線程時(shí)發(fā)生OutOfMemory導(dǎo)致進(jìn)程掛掉。

從下圖crash log可以看到有兩萬(wàn)四千個(gè)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(wàn)多個(gè)Datanode State Machine Thread掛掉。

接著分析為何有兩萬(wàn)多個(gè)Datanode State Machine Thread，代碼里可以看到該線程用線程池newCacheThreadPool創(chuàng)建。該newCacheThreadPool在沒(méi)有線程可用，例如線程都在等鎖的情況下，會(huì)創(chuàng)建新的線程，因此創(chuàng)建了兩萬(wàn)多個(gè)線程。接著分析Datanode State Machine Thread等的什么鎖。在進(jìn)程的線程數(shù)超過(guò)5000時(shí)，用jstack -l pid > jstack.txt打出所有線程的狀態(tài)。

可以看到幾乎所有Datanode State Machine Thread在等鎖，而只有一個(gè)Datanode State Machine Thread – 5500 拿到了鎖，但是卡在提交RPC請(qǐng)求submitRequest。至此Java調(diào)用C++發(fā)生Crash?和Java內(nèi)Crash的原因找到。

死鎖

log4j導(dǎo)致的死鎖

jstack打出的死鎖信息如下所示。grpc-default-executor-14765線程拿到了log4j的鎖，在等RaftServerImpl的鎖；grpc-default-executor-14776線程拿到了RaftServerImpl的鎖，在等log4j的鎖，導(dǎo)致這兩個(gè)線程都拿到了對(duì)方等待的鎖，所以造成兩個(gè)線程死鎖。可以看出，僅僅打日志的log4j，不釋放鎖是最值得懷疑的地方。最后發(fā)現(xiàn)log4j存在死鎖的缺陷[4]。該缺陷在log4j2得到解決，升級(jí)log4j即可。

封裝不嚴(yán)謹(jǐn)導(dǎo)致的死鎖

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對(duì)象，如果拿到鎖后，在創(chuàng)建新對(duì)象AutoCloseableLock時(shí)發(fā)生OOM等異常，鎖就無(wú)法釋放。

參考

[1]https://www.waitingforcode.com/apache-spark/apache-spark-off-heap-memory/read

[2]https://github.com/alibaba/arthas/releases/tag/arthas-all-3.3.6

[3]https://www.jaegertracing.io/docs/1.18/getting-started/

[4]https://stackoverflow.com/questions/3537870/production-settings-file-for-log4j/

總結(jié)

以上是生活随笔為你收集整理的Java内存泄漏、性能优化、宕机死锁的N种姿势的全部?jī)?nèi)容，希望文章能夠幫你解決所遇到的問(wèn)題。

如果覺(jué)得生活随笔網(wǎng)站內(nèi)容還不錯(cuò)，歡迎將生活随笔推薦給好友。