本番環境の障害を特定するための btrace メソッド

前書き

プログラムの実行詳細についてさらに知る必要があることがよくありますが、開発中にプログラム内のすべての実行詳細をログに出力することは不可能です。通常、現時点でできることは次のとおりです。コードを修正して再デプロイして観察するという方法がありますが、この方法はオンライン アプリケーションにはあまり適していません。一方、他の外部パッケージを参照するなど、変更が難しいコードに遭遇した場合は非常に面倒です。 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 ドライバーがシリアル要求の応答を保証するために最下層にロックを追加するためです。チャネルは遅いステートメントがブロックされているため、ロールバックはブロックされています。

btrace の運用上の障害を特定する方法に関連するその他の記事については、PHP 中国語 Web サイトに注目してください。