本文介紹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裡刪除。
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,記錄哪些內存未被釋放。
性能優化arthasperf是最為普遍的性能分析工具,在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在協議裡傳輸等。
jaegerperf適用於查找整個程序的熱點函數,但不適用於分析單次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,則時間減少一半。
tcpdumptcpdump常用來抓包分析,但也能用來優化性能。在我們的場景中,部署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請求越來越慢。優化後,性能提升一百倍。
jstackjstack用來查詢線程狀態,但在極端情況下也可以用於性能優化。在部署服務時,發現進程迅速佔滿所有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:+HeapDumpOnOutOfMemoryErrorJVM內發生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]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/