记一次使用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社区有反应过这个问题，至今未解决。

问题链接：bugs.openjdk.org/browse/JDK-…

寻觅其它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到了一种新的问题解决路径，还是非常值得的