BTrace初体验

發表於 | 分類於 | | 閱讀次數

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

背景

这次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查了异常线程的id，jstack打印出了线程堆栈，查到是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