BTrace初体验

最早听说BTrace应该是从毕大师那儿,懒得一直没有动手实验过。去年公司一位同事在内网上介绍了Byteman,倒是用来解决过两三个实际的问题。BTraceByteman都可以在不停机的情况下对程序进行诊断,各有优劣

背景

这次BTrace初体验面临的问题:

应用的一个接口使用一条非常简单的SQL查询,接口的latency时有抖动,夸张的时候到了800ms以上,怀疑是使用的数据库中间件的问题;但是数据库中间件提供的耗时统计监控显示,中间件里面的方法耗时并没有这种比较离谱的抖动。从业务机器的系统级别的监控(load/io/pcsw 等等)在抖动的时间点都看不出什么异常

应用接口和数据库中间件的方法之间还有Mybatis的逻辑,想通过Btrace脚本去观察下这部分的耗时。
Btrace@Duration这个获取方法耗时的注解,用起来比Byteman方便,所以在这个场景下选择了使用Btrace

排查过程

  1. 使用BTraceUtils.jstack获取在调用数据库中间件时的调用栈。调用了BTraceUtils.jstack之后,最好再打印一行println("============="),确保堆栈打印到屏幕上,也可以手动调用flush console output
  2. 拿到对应的调用栈,挑选几个值得怀疑的方法获取方法的执行时间
  3. 到这一步的时候,发现抖动时的耗时还是位于数据库中间件的方法里面,定位到数据库中间件的耗时统计监控处理是有些问题的
  4. 然后再一步步从数据库中间件的方法里面找可能导致抖动的方法,一直定位到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查了异常线程的idjstack打印出了线程堆栈,查到是Btrace相关的线程,堆栈如下:

    1
    2
    3
    4
    5
    6
    java.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