btrace定位生产故障

现象

某些请求通过数据访问层很慢并导致处理线程阻塞，从监控中未能检查到异常。

编写btrace脚本

@BTrace
public class DBProxyTrace {

    @OnMethod(clazz = "xxx.xxx.QueryHandler", method = "query",
            location = @Location(Kind.RETURN))
    public static void trace2(String sql, @Duration long duration) {
        if (duration/1000000 > 10 * 1000) {
            com.sun.btrace.BTraceUtils.println(duration/1000000 + "ms");
            com.sun.btrace.BTraceUtils.println("this task executes more than 10s. the sql is : "
                    + sql);
            com.sun.btrace.BTraceUtils.println("jstack is : ");
            com.sun.btrace.BTraceUtils.jstack();
        }
    }
}

判断执行大于10秒的sql和堆栈信息。

编译脚本DBProxyTrace.java，确认脚本没有问题。

./bin/btracec  -cp build/ java/DBProxyTrace.java

执行脚本DBProxyTrace.class

./bin/btrace -cp build/ 17342  DBProxyTrace.class

信息

10468ms
this task executes more than 10s. the sql is : rollback
jstack is :
xxx.QueryHandler.query(QueryHandler.java:106)
xxx.net.AbstractConnection.onReadData(AbstractConnection.java:245)
xxx.net.NIOReactor$RW.run(NIOReactor.java:77)
java.lang.Thread.run(Thread.java:745)

定位

阻塞在事务回滚。

使用jstack进一步定位。

打印JVM堆栈

"$_NIOREACTOR-7-RW" prio=10 tid=0x00007f069856f000 nid=0xde1 waiting for monitor entry [0x00007f0677011000]
   java.lang.Thread.State: BLOCKED (on object monitor)
    at oracle.jdbc.driver.PhysicalConnection.rollback(PhysicalConnection.java:1167)
    - waiting to lock <0x000000068086fbc0> (a oracle.jdbc.driver.T4CConnection)

结论

阻塞在了oracle驱动rollback动作，这里其实是因为oracle驱动为了保证串行请求响应而在底层加了锁，而这个通道被慢语句塞住了，所以rollback塞了。