.記一次使用gdb診斷gc問題全過程

扣釘日記發表於2023-02-04
原創:扣釘日記(微信公眾號ID:codelogs),歡迎分享,轉載請保留出處。

簡介

上次解決了GC長耗時問題後,系統果然平穩了許多,這是之前的文章《GC耗時高,原因竟是服務流量小?》
然而,過了一段時間,我檢查GC日誌時,又發現了一個GC問題,如下:
image_2023-02-04_20230204143644
從這個圖中可以發現,我們GC有一些尖峰,有時會突然有大量的記憶體分配。

檢視GC日誌,發現有大物件分配的記錄,如下:

$ grep 'concurrent humongous allocation' gc.log | awk 'match($0,/allocation request: (\w+) bytes/,a){print a[1]}' |sort -nr
1941835784
1889656848

image_2023-02-04_20230204143322
可以看到,一次大物件分配,分配大小竟然有1.9G,這誰能抗得住啊!

async-profiler定位大物件分配

上面提到的文章介紹過,使用async-profiler可以很容易的定位大物件分配的呼叫棧,方法如下:

./profiler.sh start --all-user -e G1CollectedHeap::humongous_obj_allocate -f ./humongous.jfr jps

然後使用jmc開啟humongous.jfr檔案,呼叫棧如下:
image_2023-02-04_20230204180005

這是在做thrift反序列化操作,呼叫了TCompactProtocol.readDouble方法,方法程式碼如下:
image_2023-02-04_20230204144842
可是,這裡只建立了8位元組的陣列,怎麼也不可能需要分配1.9G記憶體吧,真是奇了怪了!

經過一番瞭解,這是因為async-profiler是透過AsyncGetCallTrace來獲取呼叫棧的,而AsyncGetCallTrace獲取的棧有時是不準的,Java社群有反饋過這個問題,至今未解決。
image_2023-02-04_20230204171551
問題連結:https://bugs.openjdk.org/brow...

尋找其它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設定斷點,方法原始碼如下:
image_2023-02-04_20230204152845
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函式,如下:
image_2023-02-04_20230204153959
之所以要加偏移量,是因為在 + 0x58c06f - 0x58c060這個位置後,rsi暫存器(第二個引數)才會有值,之所以獲取每二個引數的值,是因為C++物件程式設計中,第一個引數是this。

然後後面的邏輯就好理解了,如下:
image_2023-02-04_20230204155401
首先是迴圈,然後continue表示讓程式執行起來,當程式命中斷點後,continue才會執行完。
中間是訊號處理,主要是為了能Ctrl+c退出迴圈。
最後透過print將rsi的值列印出來,這樣就追蹤到了word_size引數的值。

再然後是列印執行緒與呼叫棧資訊,如下:
image_2023-02-04_20230204155915
當分配記憶體大於100M時,列印當前時間、當前執行緒與當前呼叫棧。

但gdb的bt命令列印的呼叫棧是這樣子的,如下:
image_2023-02-04_20230204160314
因為Java是解釋執行的,java部分的呼叫棧bt是獲取不到的。
image_2023-02-04_20230204174258

沒有java呼叫棧,這個追蹤指令碼就瘸了呀,我在這裡卡了好久,也嘗試了許多種方法?

對java比較熟悉的同學應該知道,jvm有一個隱藏的診斷功能,如果給jvm程式發SIGQUIT訊號,jvm會在標準輸出中列印執行緒棧資訊,而SIGQUIT訊號可以透過kill -3傳送,因此就有了下面的程式碼:
image_2023-02-04_20230204161023
gdb真是強大,內嵌了python擴充套件,而透過python的subprocess包,就可以執行kill -3命令了。

後面的detachquit,用於退出gdb的,不用深究。

執行gdb指令碼追蹤大物件

把上面的gdb指令碼命名為trace.gdb,然後就可以使用gdb命令執行它了,如下:

$ gdb -q --batch -x trace.gdb -p `pgrep java`

其中pgrep java用於獲取java程式的程式號。

注:gdb本質上是基於ptrace系統呼叫的偵錯程式,斷點命中時對程式有不小切換開銷,所以這種方式只能追蹤呼叫頻次不高的函式。

執行後,追蹤到的引數與執行緒資訊如下:
image_2023-02-04_20230204162114
其中LWP後面的166就是執行緒號,轉成十六進位制就是0xa6。
然後到java程式的標準輸出日誌中,去找這個執行緒的Java呼叫棧,如下:
image_2023-02-04_20230204163200

大物件分配由readBinary函式發起,除錯下這個函式,如下:
image_2023-02-04_20230204163605
媽呀,它建立了一個超大的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程式碼,發現可以限制欄位的最大長度,如下:
image_2023-02-04_20230204165113
想一想,反序列的某個欄位的長度,肯定不會有整個反序列化的資料長呀,因此使用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到了一種新的問題解決路徑,還是非常值得的?

相關文章