btrace定位生產故障

超人汪小建發表於2019-01-24

現象

某些請求通過資料訪問層很慢並導致處理執行緒阻塞，從監控中未能檢查到異常。

編寫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塞了。

相關文章