さらに詳しく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(); }' |
画面1 Chimeを使用し、DTraceの結果をグラフで表示した例
ITmediaはアイティメディア株式会社の登録商標です。