gc突然抽出来 记一次使用gdb诊断gc问题全过程

大家好，关于gc突然抽出来很多朋友都还不太明白，今天小编就来为大家分享关于记一次使用gdb诊断gc问题全过程的知识，希望对各位有所帮助！

原创：扣钉日记（微信公众号ID：codelogs），欢迎分享，转载请保留出处。

上次解决了GC长耗时问题后，系统果然平稳了许多，这是之前的文章《GC耗时高，原因竟是服务流量小？》然而，过了一段时间，我检查GC日志时，又发现了一个GC问题，如下：

从这个图中可以发现，我们GC有一些尖峰，有时会突然有大量的内存分配。

查看GC日志，发现有大对象分配的记录，如下：

$grep'concurrenthumongousallocation'gc.log|awk'match($0,/allocationrequest:(\\w+)bytes/,a){printa[1]}'|sort-nr\n1941835784\n1889656848

可以看到，一次大对象分配，分配大小竟然有1.9G，这谁能抗得住啊！

上面提到的文章介绍过，使用async-profiler可以很容易的定位大对象分配的调用栈，方法如下：

./profiler.shstart--all-user-eG1CollectedHeap::humongous_obj_allocate-f./humongous.jfrjps

然后使用jmc打开humongous.jfr文件，调用栈如下：

这是在做thrift反序列化操作，调用了TCompactProtocol.readDouble方法，方法代码如下：

可是，这里只创建了8字节的数组，怎么也不可能需要分配1.9G内存吧，真是奇了怪了！

经过一番了解，这是因为async-profiler是通过AsyncGetCallTrace来获取调用栈的，而AsyncGetCallTrace获取的栈有时是不准的，Java社区有反馈过这个问题，至今未解决。

问题链接：https://bugs.openjdk.org/browse/JDK-8178287

linux上有很多内核态的tracer，如perf、bcc、systemtap，但它们都需要root权限，而我是不可能申请到这个权限的

在用户态上，基于ptrace系统调用实现的有strace、ltrace，我试了一下它们，并无法直接跟踪G1中的大对象分配函数G1CollectedHeap::humongous_obj_allocate。

我也在网上搜索了好几天，希望找到一个有用的纯用户态tracer，但可惜几天都没找到，最后，我只能将目标放在c/c++的调试工具gdb上，我想gdb既然是一个调试工具，那它必然能够查看指定函数的调用参数与调用栈，只要找到相应用法即可！

经过一番学习与探索(PS：其实花了我快2周)，我终于编写出了实际可用的gdb脚本，如下：

handleallnostopnoprintpass\nhandleSIGINTstopprintnopass\n\nbreak*(_ZN15G1CollectedHeap22humongous_obj_allocateEmh+0x58c06f-0x58c060)\nwhile1\ncontinue\n#如果是Ctrl+c，则退出\nif$_siginfo\nif$_siginfo.si_signo==2\ndetach\nquit\nend\nend\nprintf"word_sizeis%d\\n",$rsi\nif$rsi>100*1024*1024/8\n#打印当前时间\nshelldate+%FT%T\n#打印当前线程\nthread\n#打印当前调用栈\nbt\npythonimportsubprocess\n#向jvm发送kill-3信号，即SIGQUIT信号\npythonproc=subprocess.Popen(['kill','-3',str(gdb.selected_inferior().pid)],stdout=subprocess.PIPE,stderr=subprocess.PIPE,bufsize=1,universal_newlines=True)\npythonstdout,stderr=proc.communicate()\npythonprint(stdout)\npythonprint(stderr)\ndetach\nquit\nend\nend

没学过gdb的同学可能看不明白，没关系，我们慢慢来。

handleallnostopnoprintpass\nhandleSIGINTstopprintnopass

这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查询二进制文件的符号表，可以获取这个名称。

$whichjava\n/usr/local/jdk/jdk1.8.0_202/bin/java\n\n#jvm相关实现，都在libjvm.so动态库中\n$find/usr/local/jdk/jdk1.8.0_202|greplibjvm.so\n/usr/local/jdk/jdk1.8.0_202/jre/lib/amd64/server/libjvm.so\n\n$nm/usr/local/jdk/jdk1.8.0_202/jre/lib/amd64/server/libjvm.so|grephumongous_obj_allocate\n000000000058c060t_ZN15G1CollectedHeap22humongous_obj_allocateEmh\n000000000058b1a0t_ZN15G1CollectedHeap41humongous_obj_allocate_initialize_regionsEjjmh

再看回之前设置断点的脚本代码：

break*(_ZN15G1CollectedHeap22humongous_obj_allocateEmh+0x58c06f-0x58c060)

+0x58c06f-0x58c060这个是在做地址偏移操作，了解过汇编的同学应该清楚，调用函数后，函数开头的一些汇编指令，一般是参数寄存器的相关操作，x86参数寄存器如下：

rdi表示第一个参数\nrsi表示第二个参数\nrdx表示第三个参数\nrcx表示第四个参数\nr8表示第五个参数\nr9表示第六个参数

可以使用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脚本命名为trace.gdb，然后就可以使用gdb命令运行它了，如下：

$gdb-q--batch-xtrace.gdb-p`pgrepjava`

其中pgrepjava用于获取java进程的进程号。

注：gdb本质上是基于ptrace系统调用的调试器，断点命中时对进程有不小切换开销，所以这种方式只能追踪调用频次不高的函数。

运行后，追踪到的参数与线程信息如下：

其中LWP后面的166就是线程号，转成十六进制就是0xa6。然后到java进程的标准输出日志中，去找这个线程的Java调用栈，如下：

大对象分配由readBinary函数发起，调试下这个函数，如下：

妈呀，它创建了一个超大的byte数组，难怪会出现1.9G的大对象分配呢！

而readBinary的调用，由这个代码触发：

TProtocolFactoryfactory=newTCompactProtocol.Factory();\nTDeserializerdeserializer=newTDeserializer(factory);\ndeserializer.deserialize(deserializeObj,sourceBytes);

这是在做thrift反序列化，将sourceBytes字节数组反序列化到deserializeObj对象中。

当sourceBytes是由deserializeObj对象序列化出来时，反序列化就没有任何问题。

而当sourceBytes不是由deserializeObj对象序列化出来时，反序列化代码从sourceBytes中解析出字段长度时(length)，可能是任意值，进而导致可能创建超大的字节数组。

但我们写这个代码，就是为了检测sourceBytes是否由deserializeObj序列化而来，所以sourceBytes确实有可能不是由deserializeObj序列化而来！

简单查看了一会thrift代码，发现可以限制字段的最大长度，如下：

想一想，反序列的某个字段的长度，肯定不会有整个反序列化的数据长呀，因此使用sourceBytes.length来限制即可。

TProtocolFactoryfactory=newTCompactProtocol.Factory(sourceBytes.length,sourceBytes.length);\nTDeserializerdeserializer=newTDeserializer(factory);\ndeserializer.deserialize(deserializeObj,sourceBytes);

限制了后，若字段超长了会抛异常，所以若反序列化异常了，说明当前sourceBytes不是由deserializeObj序列化出来。

编写这个gdb脚本，确实花费了我相当多的时间，因为事前我也不知道gdb是否能够做到这个事情，且我不是C/C++程序员，对汇编相关知识并不熟悉，中途有好几次想放弃

好在最后成功了，并让我又Get到了一种新的问题解决路径，还是非常值得的

OK，本文到此结束，希望对大家有所帮助。