連載
» 2008年08月06日 00時00分 公開

DTraceでトラブルシューティングOpenSolarisで始めるブログサーバ構築(最終回)(2/4 ページ)

[原口章司,サン・マイクロシステムズ株式会社]

Javaアプリケーションを詳細にトレース

 さらに詳しくJavaアプリケーションをトレースするために、DTrace用のhotspotプロバイダが提供されています。hotspotプロバイダは、JDK 1.6で提供されている機能で、JavaとVMのイベントトレースを可能にします。hotspotプロバイダの詳細については、http://java.sun.com/javase/6/docs/technotes/guides/vm/dtrace.htmlをご覧ください。

 Javaアプリケーションの中で頻繁に呼び出されるメソッドを計測する「method_* プローブ」は、実行中のVMの性能に影響を与えるため、デフォルトでは有効状態ではありません。有効にするには、VMにExtendedDTraceProbesフラグを立てる必要があります。通常、Java実行時には、引数「-XX:+ExtendedDTraceProbes」の追加で有効になります。

# java -XX:+ExtendedDTraceProbes <Java プログラム>

 Apache Rollerでこのオプションを有効にするには、/opt/coolstack/tomcat/binディレクトリの下に「setenv.sh」という名前で、下記の内容の実行可能シェルスクリプトを作成し、Rollerを再起動する必要があります。

tomcat# cd /opt/coolstack/tomcat/bin
tomcat# cat setenv.sh
#!/bin/sh
CATALINA_OPTS="-XX:+DTraceMethodProbes"
export CATALINA_OPTS
tomcat# chmod +x setenv.sh
tomcat# svcs -a| grep tomcat
online 18:03:23 svc:/application/csk-tomcat:CSKtomcat
tomcat# svcadm restart CSKtomcat ←tomcat_zoneでtomcatを再起動します

 以下の例では、Roller実行中に呼び出されたメソッドのクラス名とメソッド名をトレースします。

hotspot$target:::method-entry
{
       printf("%s.%s\n",stringof(copyin(arg1, arg2)), stringof(copyin(arg3,arg4)));
}
jmethod_trace.d の例

 hotspot$targetの記述で、dtrace(1M)の引数に計測するRollerのプロセスIDを指定します。RollerのプロセスIDは、以下の方法で取得可能です。

tomcat# /usr/java/bin/jps -l
1839 org.apache.catalina.startup.Bootstrap ←RollerのプロセスIDとなります
2568 sun.tools.jps.Jps

 では、大域ゾーンにて、jmethod_trace.dを使ってトレースを実行してみます。

solaris# dtrace -qs jmethod_trace.d -p 1839
...
org/apache/roller/weblogger/business/WebloggerFactory.
getWeblogger
org/apache/roller/weblogger/business/jpa/JPAUserManager
Impl.getWebsiteByHandle
org/apache/roller/weblogger/business/jpa/JPAUserManager
Impl.getWebsiteByHandle
java/util/Hashtableector.containsKey
java/lang/Stringl/AbstractList$Itr.hashCodectList$Itr
...

統計情報でシステム全体の状態を把握

 実際にRollerを運用しているケースでは、1日に何百、何千と頻繁にアクセスがある場合もあります。こうしたケースでは、イベントごとの詳細トレースよりも、一定時間内にアクセスした総カウント数や書き込みアクセスにかかる平均時間などの統計情報の方が、状態を観測するうえで有効となる場合があります。

 以下に簡単な例を示します。

solaris# cat j_top5_counts.d
dtrace:::BEGIN
{
       printf("Tracing... Hit Ctrl-C to end.\n");
       top = 5;
}
hotspot*:::method-return
{
       this->class = (char *)copyin(arg1, arg2 + 1);
       this->class[arg2] = '\0';
       this->method = (char *)copyin(arg3, arg4 + 1);
       this->method[arg4] = '\0';
       this->name = strjoin(strjoin(stringof(this->class), "."),
              stringof(this->method));
       @num[pid, "method", this->name] = count();
       @num[0, "total", "-"] = count();
}
dtrace:::END
{
       trunc(@num, top);
       printf("\nTop %d counts,\n", top);
       printf(" %6s %-10s %-48s %8s\n", "PID", "TYPE", "NAME", "COUNT");
       printa(" %6d %-10s %-48s %@8d\n", @num);
}
solaris# dtrace -qs j_top5_counts.d
Tracing... Hit Ctrl-C to end.
^C
Top 5 counts,
     PID TYPE      NAME COUNT
    1839 method    java/lang/System.arraycopy     27091
    1839 method    com/mysql/jdbc/util/ReadAheadInputStream.checkClosed 33236
    1839 method    java/lang/Object.<init>        34280
    1839 method    java/lang/String.charAt        37927
       0 total     -                            1122551

 続いて、quantize()関数を使って、write()システムコールにかかった時間の統計情報をグラフで表示してみます。

solaris# cat quantise.d
syscall::write:entry
/zonename == "tomcat_zone"
&& execname =="java"/
{
self->ts[execname] = timestamp;
}
syscall::write:return
/zonename == "tomcat_zone"
&& execname == "java"
&& self->ts[execname]/
{
@[execname] = quantize(timestamp - self->ts[execname]);
self->ts[execname] = 0;
}
solaris# dtrace -s quantise.d ←quantise.d Dスクリプトを実行します
dtrace: script 'quantise.d' matched 2 probes
^C
java
       value ------------- Distribution ------------- count
       4096 |                                         0
       8192 |@@@@@@@@@@@@@@@@@@                       84
      16384 |@@@@@@@@@@@@@@@@@@@                      89
      32768 |@@@                                      16
      65536 |                                         1
     131072 |                                         0
solaris#

 OpenSolarisでは、DTraceの統計関数の出力結果をグラフィカルに出力させる「Chime(チャイム)」というツールがプロジェクトから提供されています。このツールをダウンロードし、使用した例を以下に示します。

solaris# chime -kTn 'syscall:::entry /zonename=="tomcat_zone"/ {@[execname]=count();}'
solaris# chime -kTn 'hotspot*::: { @[probename] = count(); }'

OpenSolaris 画面1 Chimeを使用し、DTraceの結果をグラフで表示した例

Copyright © ITmedia, Inc. All Rights Reserved.

RSSについて

アイティメディアIDについて

メールマガジン登録

@ITのメールマガジンは、 もちろん、すべて無料です。ぜひメールマガジンをご購読ください。