最早听说BTrace
应该是从毕大师那儿,懒得一直没有动手实验过。去年公司一位同事在内网上介绍了Byteman
,倒是用来解决过两三个实际的问题。BTrace
和Byteman
都可以在不停机的情况下对程序进行诊断,各有优劣。
背景
这次BTrace初体验面临的问题:
应用的一个接口使用一条非常简单的SQL查询,接口的latency时有抖动,夸张的时候到了800ms以上,怀疑是使用的数据库中间件的问题;但是数据库中间件提供的耗时统计监控显示,中间件里面的方法耗时并没有这种比较离谱的抖动。从业务机器的系统级别的监控(
load
/io
/pcsw
等等)在抖动的时间点都看不出什么异常
应用接口和数据库中间件的方法之间还有Mybatis
的逻辑,想通过Btrace
脚本去观察下这部分的耗时。Btrace
有@Duration
这个获取方法耗时的注解,用起来比Byteman
方便,所以在这个场景下选择了使用Btrace
。
排查过程
- 使用
BTraceUtils.jstack
获取在调用数据库中间件时的调用栈。调用了BTraceUtils.jstack
之后,最好再打印一行println("=============")
,确保堆栈打印到屏幕上,也可以手动调用flush console output
- 拿到对应的调用栈,挑选几个值得怀疑的方法获取方法的执行时间
- 到这一步的时候,发现抖动时的耗时还是位于数据库中间件的方法里面,定位到数据库中间件的耗时统计监控处理是有些问题的
- 然后再一步步从数据库中间件的方法里面找可能导致抖动的方法,一直定位到
Druid
里面,还未找到Root Cause
结果还不够好,但是借助Btrace
走出了之前的误区 :)
问题
过程人肉
上述排查过程中的第4步,是非常人肉的一个过程:
添加方法到btrace脚本
->
运行脚本->
等待抖动->
再添加方法到btrace脚本
如此往复,让人感觉乏味,即使是在运行如此强大的工具,所以需要想一些自动化或者半自动化的方法。
半自动化的思路:
- 通过
BTraceUtils.jstack
找到调用堆栈 - 在调用堆栈里面随机分段选择几个方法,生成新的
BTrace
脚本 - 根据抖动时这几个方法的执行时间进一步定位到产生抖动的方法
CandidateMethod
- 对
CandidateMethod
使用Kind.CALL
,拿到具体的耗时的方法
遗留问题
对应用程序运行过几次Btrace
脚本之后,发现了两个异常情况,暂时没有办法解释:
- 运行
Btrace
脚本时没有信息输出。胡乱折腾了下,有两个发现:- 加上-v参数之后运行btrace,发现是有输出的;去掉-v参数,就没有输出了
- 去掉一些Method之后,就有输出;加上之后就没有输出了
脚本退出之后应用程序表现异常,
cpu
跑得比较高,应用接口的latency
上涨。通过top -p $pid -H
查了异常线程的id
,jstack
打印出了线程堆栈,查到是Btrace
相关的线程,堆栈如下:123456java.lang.Thread.State: TIMED_WAITING (sleeping)at java.lang.Thread.sleep(Native Method)at com.sun.btrace.BTraceRuntime$2.idle(BTraceRuntime.java:406)at com.sun.btrace.org.jctools.queues.BaseMpscLinkedArrayQueue.drain(BaseMpscLinkedArrayQueue.java:586)at com.sun.btrace.BTraceRuntime$4.run(BTraceRuntime.java:445)at java.lang.Thread.run(Thread.java:745)一台表现异常的机器上,居然有8个这样的线程;表现正常的机器上是没有这样的线程在运行的。这个情况在毕大师的一篇博客里面也提到过类似的场景:
话说前几天我在生产环境用btrace还碰到个问题,我跟踪的那个方法输出的信息太多,结果为了让btrace停止,我按了多次ctrl+c,然后回车,估计按太多次了,竟然导致目标进程的heap被用满了,一直fgc。
这两个异常情况背后可能是同一个原因,还需要再排查下 :(
参考
[1] http://calvin1978.blogcn.com/articles/btrace1.html
[2] http://agapple.iteye.com/blog/1005918
[3] http://hellojava.info/?p=123
[4] http://hellojava.info/?p=517
[5] http://hushi55.github.io/2014/12/31/byteman