原創：扣釘日記（微信公眾號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到了一種新的問題解決路徑，還是非常值得的??