記一次使用gdb診斷gc問題全過程
原創:扣釘日記(微信公眾號ID:codelogs),歡迎分享,轉載請保留出處。
簡介
上次解決了GC長耗時問題后,系統果然平穩了許多,這是之前的文章《GC耗時高,原因竟是服務流量???》
然而,過了一段時間,我檢查GC日志時,又發現了一個GC問題,如下:
從這個圖中可以發現,我們GC有一些尖峰,有時會突然有大量的內存分配。
查看GC日志,發現有大對象分配的記錄,如下:
$ grep 'concurrent humongous allocation' gc.log | awk 'match($0,/allocation request: (\w+) bytes/,a){print a[1]}' |sort -nr
1941835784
1889656848
可以看到,一次大對象分配,分配大小竟然有1.9G,這誰能抗得住??!
async-profiler定位大對象分配
上面提到的文章介紹過,使用async-profiler可以很容易的定位大對象分配的調用棧,方法如下:
./profiler.sh start --all-user -e G1CollectedHeap::humongous_obj_allocate -f ./humongous.jfr jps
然后使用jmc打開humongous.jfr文件,調用棧如下:
這是在做thrift反序列化操作,調用了TCompactProtocol.readDouble
方法,方法代碼如下:
可是,這里只創建了8字節的數組,怎么也不可能需要分配1.9G內存吧,真是奇了怪了!
經過一番了解,這是因為async-profiler是通過AsyncGetCallTrace來獲取調用棧的,而AsyncGetCallTrace獲取的棧有時是不準的,Java社區有反饋過這個問題,至今未解決。
問題鏈接:https://bugs.openjdk.org/browse/JDK-8178287
尋找其它tracer
linux上有很多內核態的tracer,如perf、bcc、systemtap,但它們都需要root權限,而我是不可能申請到這個權限的??
在用戶態上,基于ptrace系統調用實現的有strace、ltrace,我試了一下它們,并無法直接跟蹤G1中的大對象分配函數G1CollectedHeap::humongous_obj_allocate
。
我也在網上搜索了好幾天,希望找到一個有用的純用戶態tracer,但可惜幾天都沒找到,最后,我只能將目標放在c/c++的調試工具gdb上,我想gdb既然是一個調試工具,那它必然能夠查看指定函數的調用參數與調用棧,只要找到相應用法即可!
編寫gdb腳本
經過一番學習與探索(PS:其實花了我快2周??),我終于編寫出了實際可用的gdb腳本,如下:
handle all nostop noprint pass
handle SIGINT stop print nopass
break *(_ZN15G1CollectedHeap22humongous_obj_allocateEmh + 0x58c06f - 0x58c060)
while 1
continue
# 如果是Ctrl+c,則退出
if $_siginfo
if $_siginfo.si_signo == 2
detach
quit
end
end
printf "word_size is %d\n",$rsi
if $rsi > 100*1024*1024/8
# 打印當前時間
shell date +%FT%T
# 打印當前線程
thread
# 打印當前調用棧
bt
python import subprocess
# 向jvm發送kill -3信號,即SIGQUIT信號
python proc = subprocess.Popen(['kill','-3',str(gdb.selected_inferior().pid)], stdout=subprocess.PIPE, stderr=subprocess.PIPE, bufsize=1, universal_newlines=True)
python stdout, stderr = proc.communicate()
python print(stdout)
python print(stderr)
detach
quit
end
end
沒學過gdb的同學可能看不明白,沒關系,我們慢慢來。
handle all nostop noprint pass
handle SIGINT stop print nopass
這2句handle是處理Linux信號用的,由于我們并不需要調試信號問題,所以讓gdb都不處理信號,保留SIGINT是為了按Ctrl+c時能退出gdb腳本。
break *(_ZN15G1CollectedHeap22humongous_obj_allocateEmh + 0x58c06f - 0x58c060)
這個break是給G1中的大對象分配函數G1CollectedHeap::humongous_obj_allocate
設置斷點,方法源碼如下:
word_size參數表示分配多少字的內存,而在64位機器上,1字等于8字節,所以如果能追蹤到這個參數值,就能知道每次分配大對象的大小了。
由于JVM是使用C++寫的,而C++編譯會做函數名改寫(mangle)以兼容C的ABI,所以編譯后的函數名就變成了奇奇怪怪的_ZN15G1CollectedHeap22humongous_obj_allocateEmh
,通過nm查詢二進制文件的符號表,可以獲取這個名稱。
$ which java
/usr/local/jdk/jdk1.8.0_202/bin/java
# jvm相關實現,都在libjvm.so動態庫中
$ find /usr/local/jdk/jdk1.8.0_202 | grep libjvm.so
/usr/local/jdk/jdk1.8.0_202/jre/lib/amd64/server/libjvm.so
$ nm /usr/local/jdk/jdk1.8.0_202/jre/lib/amd64/server/libjvm.so |grep humongous_obj_allocate
000000000058c060 t _ZN15G1CollectedHeap22humongous_obj_allocateEmh
000000000058b1a0 t _ZN15G1CollectedHeap41humongous_obj_allocate_initialize_regionsEjjmh
再看回之前設置斷點的腳本代碼:
break *(_ZN15G1CollectedHeap22humongous_obj_allocateEmh + 0x58c06f - 0x58c060)
+ 0x58c06f - 0x58c060
這個是在做地址偏移操作,了解過匯編的同學應該清楚,調用函數后,函數開頭的一些匯編指令,一般是參數寄存器的相關操作,x86參數寄存器如下:
rdi 表示第一個參數
rsi 表示第二個參數
rdx 表示第三個參數
rcx 表示第四個參數
r8 表示第五個參數
r9 表示第六個參數
可以使用objdump反匯編libjvm.so,看看匯編代碼,以確定斷點該偏移到哪一行指令上,看官們堅持住,匯編相關內容就下面一點??
$ objdump -d /usr/local/jdk/jdk1.8.0_202/jre/lib/amd64/server/libjvm.so |less -S
然后在less里面搜索_ZN15G1CollectedHeap22humongous_obj_allocateEmh
函數,如下:
之所以要加偏移量,是因為在 + 0x58c06f - 0x58c060
這個位置后,rsi寄存器(第二個參數)才會有值,之所以獲取每二個參數的值,是因為C++對象編程中,第一個參數是this。
然后后面的邏輯就好理解了,如下:
首先是循環,然后continue表示讓程序運行起來,當程序命中斷點后,continue才會執行完。
中間是信號處理,主要是為了能Ctrl+c退出循環。
最后通過print將rsi的值打印出來,這樣就追蹤到了word_size參數的值。
再然后是打印線程與調用棧信息,如下:
當分配內存大于100M時,打印當前時間、當前線程與當前調用棧。
但gdb的bt命令打印的調用棧是這樣子的,如下:
因為Java是解釋執行的,java部分的調用棧bt是獲取不到的。
沒有java調用棧,這個追蹤腳本就瘸了呀,我在這里卡了好久,也嘗試了許多種方法??
對java比較熟悉的同學應該知道,jvm有一個隱藏的診斷功能,如果給jvm進程發SIGQUIT信號,jvm會在標準輸出中打印線程棧信息,而SIGQUIT信號可以通過kill -3
發送,因此就有了下面的代碼:
gdb真是強大,內嵌了python擴展,而通過python的subprocess包,就可以執行kill -3
命令了。
后面的detach
與quit
,用于退出gdb的,不用深究。
運行gdb腳本追蹤大對象
把上面的gdb腳本命名為trace.gdb,然后就可以使用gdb命令運行它了,如下:
$ gdb -q --batch -x trace.gdb -p `pgrep java`
其中pgrep java
用于獲取java進程的進程號。
注:gdb本質上是基于ptrace系統調用的調試器,斷點命中時對進程有不小切換開銷,所以這種方式只能追蹤調用頻次不高的函數。
運行后,追蹤到的參數與線程信息如下:
其中LWP后面的166就是線程號,轉成十六進制就是0xa6。
然后到java進程的標準輸出日志中,去找這個線程的Java調用棧,如下:
大對象分配由readBinary函數發起,調試下這個函數,如下:
媽呀,它創建了一個超大的byte數組,難怪會出現1.9G的大對象分配呢!
而readBinary的調用,由這個代碼觸發:
TProtocolFactory factory = new TCompactProtocol.Factory();
TDeserializer deserializer = new TDeserializer(factory);
deserializer.deserialize(deserializeObj, sourceBytes);
這是在做thrift反序列化,將sourceBytes字節數組反序列化到deserializeObj對象中。
當sourceBytes是由deserializeObj對象序列化出來時,反序列化就沒有任何問題。
而當sourceBytes不是由deserializeObj對象序列化出來時,反序列化代碼從sourceBytes中解析出字段長度時(length),可能是任意值,進而導致可能創建超大的字節數組。
但我們寫這個代碼,就是為了檢測sourceBytes是否由deserializeObj序列化而來,所以sourceBytes確實有可能不是由deserializeObj序列化而來!
簡單查看了一會thrift代碼,發現可以限制字段的最大長度,如下:
想一想,反序列的某個字段的長度,肯定不會有整個反序列化的數據長呀,因此使用sourceBytes.length來限制即可。
TProtocolFactory factory = new TCompactProtocol.Factory(sourceBytes.length, sourceBytes.length);
TDeserializer deserializer = new TDeserializer(factory);
deserializer.deserialize(deserializeObj, sourceBytes);
限制了后,若字段超長了會拋異常,所以若反序列化異常了,說明當前sourceBytes不是由deserializeObj序列化出來。
總結
編寫這個gdb腳本,確實花費了我相當多的時間,因為事前我也不知道gdb是否能夠做到這個事情,且我不是C/C++程序員,對匯編相關知識并不熟悉,中途有好幾次想放棄??
好在最后成功了,并讓我又Get到了一種新的問題解決路徑,還是非常值得的??