应用周期性fullgc问题排查(2)

289 阅读5分钟

一、背景

     上次分析了某应用生产环境周期性fullgc问题,具体参考应用真线周期性fullgc问题(1),不过定位到该问题的原因也是比较巧合,刚好网上遇到了类似周期性fullgc的问题,所以可以准确定位到是cxf包引入导致的,这就类似于反正法,我知道了结果,然后我去证明该应用周期性fullgc是由于该问题引起的;上文结尾也给出了几种正向排查的方法,将fullgc时候的堆栈信息打印出来,以此来印证确实是cxf造成的。本次分析采用了btrace这一开源工具准确定位到调用System.gc的方法;

二、BTrace简介

     生产环境系统发生问题时,定位问题需要获取系统运行时的相关数据,如方法参数、返回值、全局变量、堆栈信息等。为了获取这些数据,需要修改代码,将数据输出到日志文件,再发布到生产环境。这种方式,一方面将增大定位问题的成本和周期,对于紧急问题无法做到及时定位及解决;另一方面重新部署后环境很大程度上已被破坏,很难重现问题。BTrace在这种背景环境下应运而生了。Btrace (Byte Trace)是sun推出的一款Java 动态、安全追踪(监控)工具,可以在不停机的情况下监控系统运行情况,并且做到最少的侵入,占用最少的系统资源。BTrace通过动态(字节码)检测正在运行的Java程序的类来工作。BTrace将跟踪操作插入到正在运行的Java程序的类中,并对跟踪的程序类进行热交换。github:github.com/btraceio/bt…。BTrace在使用上做了很多限制,如不能创建对象、不能使用数组、不能抛出或捕获异常、不能使用循环、不能使用synchronized关键字、脚本的属性和方法都必须使用static修饰等,具体限制条件可参考用户手册。如果想深入了解,可以网上自行查找,相关资料比较多;

三、BTrace本地使用

      3.1 首先是要下载Btrace相关的jar包,目前github上最新的是V2.0.0,也可以下载源码,自行编译打包(不过源码不是maven项目是gradle项目); 图1  Btrace最新版V2.0.0 网上找了一个V1.3.11.3的版本,与V2.0.0最大的区别就是类路径做了调整,老版的在com.sun.btrace包下,新版的在org.openjdk.btrace下面;其他更为详细区别可以看github上的介绍; 3.2 配置环境变量
sudo vi ~/.bash_profile  图2  配置jdk、btrace环境变量 source ~/.bash_profile 使配置生效 echo $PATH 查看配置是否生效 3.3 写监听脚本 图3  btrace监听脚本 图4  btrace-bin包结构       直接使用build里面已经打包好的jar包,如上图BtraceTest就是一个监听类,monitor方法表示的是监听所有调用System.gc的方法,将其调用栈详细打印出来;当然还有好多其他用法,请自行查看相关资料,本文不再扩展; 另:最好在脚本里面只使用btrace和jdk包下的类,使用其他的在运行的时候可能会报找不到该类的错误(当然也有对应的解决办法。。。。。。); 注:脚本可以不需要放在需要排查的项目里,可以在任意目录下创建,这样使用btrace可以实现对业务代码的零侵入性,对业务代码而言是无感知的,这样就可以做到上面提到的在不停机的情况下监控系统运行情况; 3.4 运行脚本 先运行需要观测的应用,jps获取对应的进程号如图5,运行脚本如图6: /Users/xxx/Documents/btrace-bin/bin/btrace -v 12595 /Users/xxx/IdeaProjects/myProjects/easyexcel/easyexcel-boot/src/main/java/cn/com/lyd/easyexcel/boot/scripts/BtraceTest.java (进程号不一致,是因为截图时间不一样,忽略哈。。。) 图5 获取项目运行的进程号 图6  执行btrace脚本 3.6 排查分析 由图6可知可以定位到是sun.misc.GC这个类下的内部静态类Daemon,这是一个守护线程: 图7  调用System.gc的源码       图7这个和上次分析定位到一致,具体源码解析,可以参考应用周期性fullgc问题(1); 那么具体是哪里创建了该线程,接下去使用2种方法进行分析定位: 方法一: 图8 Gc.requestLatebcy方法 根据调用链路可知Gc类中创建Daemon守护线程的的是图8中的requestLatebcy方法, 图9  requestLatebcy方法调用 由图9可以看到requestLatebcy方法有2处调用,分别是图10的JDKBugHacks和图11的JreMemoryLeakPreventionListener 图10 JDKBugHacks类 图11   JreMemoryLeakPreventionListener类 由上次应用周期性fullgc问题(1)中分析可知,requestLatebcy方法的入参就是fullgc的周期,结合由图10、11的入参,真线上周期是10小时,因此可知调用requestLatebcy创建线程的就是JDKBugHacks类的doHacks方法; 方法二: 其实定位是哪个地方调用了线程的create方法,除了上面介绍的常规方法,还可以使用本文介绍的btrace方法,添加监听脚本 图12 监听sun.misc.Gc.Daemon线程的create方法 图13 btrace打印出的调用栈 如图13,根据btrace打印出来的调用链路,可以非常清晰的知道就是apache下的cxf包的JDKBugs.doHacks创建了该线程如图14,spring框架在初始化加载的时候调用了cxf包下的类,这就是为什么引入了该包,inquiry项目中没有使用到,但是却会调用JDKBugs.doHacks方法的原因; 图14  JDKBugs.dohacks方法 执行脚本的时候,项目刚启动的时候没有进行fullgc,这个也是比较困惑的,其实真线每次启动的时候是有fullgc一次的,但是本地却没有出现,查看源码分析,是由于GC.maxObjectInspectionAge(),如图15这个值会决定第一次会不会执行System.gc,每次启动该值都是不一样的,由于这个值是native修饰的,不知道具体的实现逻辑,所以只能先前一晚9点多开始跑,然后等到第二天7点多在查看运行结果; 图15 Daemon线程