簡(jiǎn)介

上次解決了GC長(zhǎng)耗時(shí)問題后，系統(tǒng)果然平穩(wěn)了許多，這是之前的文章《GC耗時(shí)高，原因竟是服務(wù)流量??？》
然而，過了一段時(shí)間，我檢查GC日志時(shí)，又發(fā)現(xiàn)了一個(gè)GC問題，如下：

image.png

查看GC日志，發(fā)現(xiàn)有大對(duì)象分配的記錄，如下：

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

image.png

async-profiler定位大對(duì)象分配

上面提到的文章介紹過，使用async-profiler可以很容易的定位大對(duì)象分配的調(diào)用棧，方法如下：

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

然后使用jmc打開humongous.jfr文件，調(diào)用棧如下：

image.png

這是在做thrift反序列化操作，調(diào)用了TCompactProtocol.readDouble方法，方法代碼如下：

image.png

經(jīng)過一番了解，這是因?yàn)閍sync-profiler是通過AsyncGetCallTrace來獲取調(diào)用棧的，而AsyncGetCallTrace獲取的棧有時(shí)是不準(zhǔn)的，Java社區(qū)有反饋過這個(gè)問題，至今未解決。

image.png

尋找其它tracer

linux上有很多內(nèi)核態(tài)的tracer，如perf、bcc、systemtap，但它們都需要root權(quán)限，而我是不可能申請(qǐng)到這個(gè)權(quán)限的??

在用戶態(tài)上，基于ptrace系統(tǒng)調(diào)用實(shí)現(xiàn)的有strace、ltrace，我試了一下它們，并無法直接跟蹤G1中的大對(duì)象分配函數(shù)G1CollectedHeap::humongous_obj_allocate。

我也在網(wǎng)上搜索了好幾天，希望找到一個(gè)有用的純用戶態(tài)tracer，但可惜幾天都沒找到，最后，我只能將目標(biāo)放在c/c++的調(diào)試工具gdb上，我想gdb既然是一個(gè)調(diào)試工具，那它必然能夠查看指定函數(shù)的調(diào)用參數(shù)與調(diào)用棧，只要找到相應(yīng)用法即可！

編寫gdb腳本

經(jīng)過一番學(xué)習(xí)與探索(PS：其實(shí)花了我快2周??)，我終于編寫出了實(shí)際可用的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
        # 打印當(dāng)前時(shí)間
        shell date +%FT%T   
        # 打印當(dāng)前線程
        thread              
        # 打印當(dāng)前調(diào)用棧
        bt                  
        python import subprocess
        # 向jvm發(fā)送kill -3信號(hào)，即SIGQUIT信號(hào)
        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

沒學(xué)過gdb的同學(xué)可能看不明白，沒關(guān)系，我們慢慢來。

handle all nostop noprint pass
handle SIGINT stop print nopass

這2句handle是處理Linux信號(hào)用的，由于我們并不需要調(diào)試信號(hào)問題，所以讓gdb都不處理信號(hào)，保留SIGINT是為了按Ctrl+c時(shí)能退出gdb腳本。

break *(_ZN15G1CollectedHeap22humongous_obj_allocateEmh + 0x58c06f - 0x58c060)

這個(gè)break是給G1中的大對(duì)象分配函數(shù)G1CollectedHeap::humongous_obj_allocate設(shè)置斷點(diǎn)，方法源碼如下：

image.png

由于JVM是使用C++寫的，而C++編譯會(huì)做函數(shù)名改寫(mangle)以兼容C的ABI，所以編譯后的函數(shù)名就變成了奇奇怪怪的_ZN15G1CollectedHeap22humongous_obj_allocateEmh，通過nm查詢二進(jìn)制文件的符號(hào)表，可以獲取這個(gè)名稱。

$ which java
/usr/local/jdk/jdk1.8.0_202/bin/java

# jvm相關(guān)實(shí)現(xiàn)，都在libjvm.so動(dòng)態(tài)庫中
$ 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

再看回之前設(shè)置斷點(diǎn)的腳本代碼：

break *(_ZN15G1CollectedHeap22humongous_obj_allocateEmh + 0x58c06f - 0x58c060)

+ 0x58c06f - 0x58c060這個(gè)是在做地址偏移操作，了解過匯編的同學(xué)應(yīng)該清楚，調(diào)用函數(shù)后，函數(shù)開頭的一些匯編指令，一般是參數(shù)寄存器的相關(guān)操作，x86參數(shù)寄存器如下：

rdi 表示第一個(gè)參數(shù)
rsi 表示第二個(gè)參數(shù)
rdx 表示第三個(gè)參數(shù)
rcx 表示第四個(gè)參數(shù)
r8 表示第五個(gè)參數(shù)
r9 表示第六個(gè)參數(shù)

可以使用objdump反匯編libjvm.so，看看匯編代碼，以確定斷點(diǎn)該偏移到哪一行指令上，看官們堅(jiān)持住，匯編相關(guān)內(nèi)容就下面一點(diǎn)??

$ objdump -d /usr/local/jdk/jdk1.8.0_202/jre/lib/amd64/server/libjvm.so |less -S

然后在less里面搜索_ZN15G1CollectedHeap22humongous_obj_allocateEmh函數(shù)，如下：

image.png

然后后面的邏輯就好理解了，如下：

image.png

再然后是打印線程與調(diào)用棧信息，如下：

image.png

但gdb的bt命令打印的調(diào)用棧是這樣子的，如下：

image.png

image.png

沒有java調(diào)用棧，這個(gè)追蹤腳本就瘸了呀，我在這里卡了好久，也嘗試了許多種方法??

對(duì)java比較熟悉的同學(xué)應(yīng)該知道，jvm有一個(gè)隱藏的診斷功能，如果給jvm進(jìn)程發(fā)SIGQUIT信號(hào)，jvm會(huì)在標(biāo)準(zhǔn)輸出中打印線程棧信息，而SIGQUIT信號(hào)可以通過kill -3發(fā)送，因此就有了下面的代碼：

image.png

后面的detach與quit，用于退出gdb的，不用深究。

運(yùn)行g(shù)db腳本追蹤大對(duì)象

把上面的gdb腳本命名為trace.gdb，然后就可以使用gdb命令運(yùn)行它了，如下：

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

其中pgrep java用于獲取java進(jìn)程的進(jìn)程號(hào)。

注：gdb本質(zhì)上是基于ptrace系統(tǒng)調(diào)用的調(diào)試器，斷點(diǎn)命中時(shí)對(duì)進(jìn)程有不小切換開銷，所以這種方式只能追蹤調(diào)用頻次不高的函數(shù)。

運(yùn)行后，追蹤到的參數(shù)與線程信息如下：

image.png

image.png

大對(duì)象分配由readBinary函數(shù)發(fā)起，調(diào)試下這個(gè)函數(shù)，如下：

image.png

而readBinary的調(diào)用，由這個(gè)代碼觸發(fā)：

TProtocolFactory factory = new TCompactProtocol.Factory();
TDeserializer deserializer = new TDeserializer(factory);
deserializer.deserialize(deserializeObj, sourceBytes);

這是在做thrift反序列化，將sourceBytes字節(jié)數(shù)組反序列化到deserializeObj對(duì)象中。

當(dāng)sourceBytes是由deserializeObj對(duì)象序列化出來時(shí)，反序列化就沒有任何問題。

而當(dāng)sourceBytes不是由deserializeObj對(duì)象序列化出來時(shí)，反序列化代碼從sourceBytes中解析出字段長(zhǎng)度時(shí)(length)，可能是任意值，進(jìn)而導(dǎo)致可能創(chuàng)建超大的字節(jié)數(shù)組。

但我們寫這個(gè)代碼，就是為了檢測(cè)sourceBytes是否由deserializeObj序列化而來，所以sourceBytes確實(shí)有可能不是由deserializeObj序列化而來！

簡(jiǎn)單查看了一會(huì)thrift代碼，發(fā)現(xiàn)可以限制字段的最大長(zhǎng)度，如下：

image.png

TProtocolFactory factory = new TCompactProtocol.Factory(sourceBytes.length, sourceBytes.length);
TDeserializer deserializer = new TDeserializer(factory);
deserializer.deserialize(deserializeObj, sourceBytes);

限制了后，若字段超長(zhǎng)了會(huì)拋異常，所以若反序列化異常了，說明當(dāng)前sourceBytes不是由deserializeObj序列化出來。

總結(jié)

編寫這個(gè)gdb腳本，確實(shí)花費(fèi)了我相當(dāng)多的時(shí)間，因?yàn)槭虑拔乙膊恢纆db是否能夠做到這個(gè)事情，且我不是C/C++程序員，對(duì)匯編相關(guān)知識(shí)并不熟悉，中途有好幾次想放棄??

好在最后成功了，并讓我又Get到了一種新的問題解決路徑，還是非常值得的??