btrace定位生產故障的方法

前言

很多時候我們需要知道更多的程式的運作細節，但又不可能在開發的時候就把程式中所有的運作細節都列印到日誌上，通常這個時候能採取的就是修改程式碼，重新部署，然後再觀察，但這種方法對於online應用來說不是很好，另外一方面如果碰到不好改的程式碼，例如引用的其他的外部的包什麼的，就很麻煩了，BTrace就是一個可以在不改代碼、不重啟應用的情況下，動態的查看程序運行細節的工具，下面這篇文章就介紹了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塞了。

更多btrace定位生產故障的方法相關文章請關注PHP中文網！