![閉じる [x]](http://dw1.s81c.com/i/c.gif){kind=small}
前回の記事では、AspectWerkzフレームワークを使って、パフォーマンス・トレースを行う基本的なアスペクトの実装について解説しました。今回は、このアスペクトをさらに進め、最初に幾つか便利な機能を追加し、次にそれを実世界の複雑なコード実体（Apache AxisのWebサービス・フレームワーク）の解析に応用します。この例を見ると、パフォーマンス・トレースにおけるアスペクト指向の利点と限界、またAOP（aspect-oriented programming: アスペクト指向プログラミング）をロギングやトレース一般に応用した場合の一般的な利点も理解できると思います。
Axisに手を染める前に、もう一つ、取り上げておくべき問題があります。前回のパフォーマンス・トレース・アスペクトでも、Javaプログラミング・ダイナミックスのシリーズ（参考文献）の初期の記事でも、私はメソッドのタイミング情報を使って、アプリケーションのパフォーマンス問題を見てきました。この手法は、幾つかの状況で私が個人的に便利だと思ったものですが、これを繰り返して使うのであれば、これに付随する問題についても議論しておくべきでしょう。そこで、こうした問題を、このコラムの初めの部分で説明しておくことにします。
このパフォーマンス・トレース・アスペクトの主な目的は、プログラムの実行を監視することです。それによって、実行時間がかかっている部分はどこかに関して、（一般的にプロファイラーで得られるボトムアップのビューとは逆に）トップダウンのビューを提供します。このアスペクトを効果的に応用するためには、時間の計測方法について、少し理解しておく必要があります。
Javaプログラミング言語には、最初のリリース以来、標準APIの一部としてタイミング・メソッドが1つありました。このメソッドはjava.lang.System.currentTimeMillis()であり、UTCでの1970年1月1日の零時からの経過時間を、ミリ秒で返します。このメソッドは、どのバージョンのJavaプラットフォームでも利用できるため、非常に便利なものです。その理由から、私は前回の最初のアスペクト・デモ・コードでも、これを使いました。しかしcurrentTimeMillis()には、少し欠点があるのです。
currentTimeMillis()の問題の一つは、時間の値はミリ秒のカウントとして返されるものの、返されるカウントのキメの細かさや精度について、何ら保証がないのです。一部のシステムでは、時間は真にミリ秒のカウントであり、ほぼ毎ミリ秒でカウントが変化します。一方、他のシステムでは、時間は10ミリ秒とか20ミリ秒の間隔でしか変化せず、しかもカウントの変化毎に精度も変化してしまうのです。
もう一つは、このメソッドの定義に特有な、基本的なタイムスケールの制限です。Javaプラットフォームが初めて使われるようになった頃には、ミリ秒は、（特にインタープリター言語では）まだ十分短い時間間隔でした。ところが今日のCPUクロック・スピードはJavaプラットフォームが初めてリリースされた頃から約100倍も早くなっているため、ミリ秒では時間間隔として比較的長いものとなってしまいました。
こうした問題の他に、currentTimeMillis()には別の懸念もあります。これは、どんな形式であれ、タイマー・メソッドをプログラム実行の監視に使うことに関する懸念です。つまり、タイマーにアクセスするために、恐らくタイマー・メソッド自体がOS（オペレーティング・システム）レベルにまで入り込む必要があることから、オーバーヘッドが追加されるのではないか、という懸念です。もし、タイマー・メソッドのオーバーヘッドが大きすぎると（あるいは、このメソッドが頻繁に呼ばれてしまうと）タイミング測定を大きく歪めてしまうことになります。私のパフォーマンス・トレース・アスペクトをインテリジェントに使うためには、タイマー・メソッドのコールによってどの程度オーバーヘッドが追加されるかに関して、少なくとも大まかに知っておく必要があります。
currentTimeMillis()を使うことに関して、どれくらい注意すべきなのでしょう。それを調べるために、私はちょっとしたテストをするプログラムを書いてみました。このプログラムをリスト1に示しますが、戻り値が変化するまでこのメソッドを呼び続ける、という非常に単純な方法で、currentTimeMillis()のキメ細かさと精度、オーバーヘッドをチェックしています。変化の大きさでタイマーのキメ細かさが分かり、戻り値が変化する間に呼ばれたコールの数によってコール毎のオーバーヘッドが分かります。また変化の大きさ、及び戻り値が変化する間に呼ばれたコール数が、どの程度一貫しているかによって、精度をチェックすることができます。
リスト1. currentTimeMillis()のキメ細かさ
public class MilliGran
{
// round value to a single digit after decimal point
private static String roundOneDecimal(double value) {
int whole = (int)value;
return whole + "." + (int)((value-whole)*10.0);
}
// print average and deviation with lead text
private static void print(String lead, double sum,
double ssqr, int reps) {
double mean = sum / reps;
double stddev = Math.sqrt(ssqr/reps-mean*mean);
System.out.println(lead + roundOneDecimal(mean) +
", with standard deviation " + roundOneDecimal(stddev));
}
public static void main(String[] argv) {
// get control values from command line
int reps = Integer.parseInt(argv[0]);
int sets = Integer.parseInt(argv[1]);
// loop until time rolls over
long start = System.currentTimeMillis();
long last;
while ((last = System.currentTimeMillis()) == start);
// loop for count of sets specified
int[] diffs = new int[reps];
for (int i = 0; i < sets; i++) {
double lsum = 0.0;
double lsumsq = 0.0;
double dsum = 0.0;
double dsumsq = 0.0;
for (int j = 0; j < reps; j++) {
// count loops until result changes
int loop = 0;
last = System.currentTimeMillis();
long now;
do {
loop++;
now = System.currentTimeMillis();
} while (now == last);
// accumulate statistics information
lsum += loop;
lsumsq += loop*loop;
int diff = (int)(now-last);
dsum += diff;
dsumsq += diff*diff;
diffs[j] = diff;
}
// print results for set
System.out.println("Set " + i + " results:");
print(" Average time change ", dsum, dsumsq, reps);
print(" Average calls before change ", lsum, lsumsq, reps);
System.out.println(" Average time per call " +
roundOneDecimal(dsum / lsum * 1000000.0) + " nanoseconds");
System.out.print(" Differences:");
for (int j = 0; j < reps; j++) {
System.out.print(" " + diffs[j]);
}
System.out.println();
}
}
}
|
リスト2は、このプログラムを、JDK 1.4.2を使って私のノートPC（比較的遅い1GHz PIIImを使ってMandrake Linux 10.0を実行しています）で実行した結果を示しています。この結果を見ると、currentTimeMillis()での時間変化は、このサンプルの期間中、常に1ミリ秒であり、このメソッドを呼ぶためのオーバーヘッドの平均は、たった約3ミリ秒です。どちらの値も一貫性がある（この場合1％以内）ため、少なくともタイマーの値は正確と考えても妥当、と言うことができます。
リスト2. currentTimeMillis()テストを実行した結果
[dennis@notebook time]$ java -cp . MilliGran 10 4
Set 0 results:
Average time change 1.0, with standard deviation 0.0
Average calls before change 332.8, with standard deviation 39.4
Average time per call 3004.8 nanoseconds
Differences: 1 1 1 1 1 1 1 1 1 1
Set 1 results:
Average time change 1.0, with standard deviation 0.0
Average calls before change 338.6, with standard deviation 38.7
Average time per call 2953.3 nanoseconds
Differences: 1 1 1 1 1 1 1 1 1 1
Set 2 results:
Average time change 1.0, with standard deviation 0.0
Average calls before change 333.6, with standard deviation 33.5
Average time per call 2996.7 nanoseconds
Differences: 1 1 1 1 1 1 1 1 1 1
Set 3 results:
Average time change 1.0, with standard deviation 0.0
Average calls before change 336.8, with standard deviation 41.4
Average time per call 2969.1 nanoseconds
Differences: 1 1 1 1 1 1 1 1 1 1
|
SunはJDK 5.0で、もっと精度の高いタイミング情報を提供するために、java.lang.System.nanoTime()という別のメソッドを追加しました。名前からも分かるように、nanoTime()は時間の値をナノ秒単位で返すため、精度はcurrentTimeMillis()メソッドよりも100万倍良くなります。現在では、ナノ秒の分解能を提供できるシステムはほとんどありませんが、少なくとも実際の値は、今までのメソッドで得られる値よりも、ずっと良くなります。
リスト1のコードを修正して、currentTimeMillis()の代わりにnanoTime()メソッドを使うようにするのは簡単です。ここでは修正したコードは示しませんが（参考文献のセクションにあるダウンロードには含まれています）、リスト3は、修正したプログラムをJDK 5.0を使って実行した結果を示しています。
リスト3. nanoTime()テストを実行した結果
[dennis@notebook time]$ java -cp . NanoGran 10 4
Set 0 results:
Average time change 2800.0, with standard deviation 400.0
Average calls before change 1.0, with standard deviation 0.0
Average time per call 2800.0 nanoseconds
Differences: 3000 3000 3000 3000 2000 2000 3000 3000 3000 3000
Set 1 results:
Average time change 2900.0, with standard deviation 300.0
Average calls before change 1.0, with standard deviation 0.0
Average time per call 2900.0 nanoseconds
Differences: 3000 3000 3000 3000 3000 3000 2000 3000 3000 3000
Set 2 results:
Average time change 2700.0, with standard deviation 458.2
Average calls before change 1.0, with standard deviation 0.0
Average time per call 2700.0 nanoseconds
Differences: 2000 3000 3000 2000 3000 3000 3000 3000 3000 2000
Set 3 results:
Average time change 2900.0, with standard deviation 300.0
Average calls before change 1.0, with standard deviation 0.0
Average time per call 2900.0 nanoseconds
Differences: 3000 3000 3000 3000 2000 3000 3000 3000 3000 3000
|
リスト3に示した結果から分かるように、nanoTime()メソッドはcurrentTimeMillis()よりも、わずかに速く実行します。しかしもっと重要なことは、このメソッドが（明らかに1000ナノ秒、つまり1マイクロ秒の細かさで）、呼ばれる度に異なる値を返す、という点です。キメ細かくなったことは、どうやって分かるのでしょう。この結果だけでは確実に分かりませんが、nanoTime()を連続的に呼んだ結果返される値同士の差が常に2、3マイクロ秒という事実がその印、と言うことができるでしょう。
前回のコラムで使ったパフォーマンス・トレースのアスペクトを、nanoTime()を使うように変更するのは簡単です。その変更を加えると同時に、このテストに合うように、コードの使いやすさを改善し、より柔軟にするための変更も加えることにします。リスト4は、変更したコードの全体です。
リスト4. パフォーマンス・トレース・アスペクトのコード
public class TraceAspect
{
private static final long DEFAULT_MINIMUM = 1000000;
private final long m_minimumNanoseconds;
private final int m_maximumNesting;
private final String m_triggerClass;
private final String m_triggerName;
private int m_matchDepth;
private int m_nestingDepth;
private ArrayList m_pendingPrints = new ArrayList();
public TraceAspect(AspectContext context) {
// set minimum time value for tracing a method
String value = context.getParameter("minimum-time");
m_minimumNanoseconds = (value == null) ?
DEFAULT_MINIMUM : Long.parseLong(value);
// set maximum depth to be printed
value = context.getParameter("maximum-depth");
m_maximumNesting = (value == null) ?
Integer.MAX_VALUE : Integer.parseInt(value);
// set trigger class and method name if supplied
value = context.getParameter("trigger-method");
if (value == null) {
m_matchDepth = 1;
m_triggerClass = null;
m_triggerName = null;
} else {
int split = value.lastIndexOf('.');
m_triggerClass = value.substring(0, split);
m_triggerName = value.substring(split+1);
}
}
private void indent(int depth) {
for (int i = 0; i < depth; i++) {
System.out.print((i % 2 == 0) ? ' ' : '-');
}
}
private void indent() {
indent(m_nestingDepth);
}
private void printFullMethod(JoinPoint call) {
MethodSignature signature = (MethodSignature)call.getSignature();
System.out.print(signature.getDeclaringType().getName());
System.out.print('.');
System.out.print(signature.getName());
}
public Object trace(JoinPoint join) throws Throwable {
// check for match on trigger
boolean match = false;
MethodSignature signature = (MethodSignature)join.getSignature();
if (signature.getName().equals(m_triggerName)) {
if (signature.getDeclaringType().getName().equals(m_triggerClass)) {
match = true;
m_matchDepth++;
}
}
// check if execution is to be processed
if (m_matchDepth == 0 || m_nestingDepth > m_maximumNesting) {
// skip any timing or printing
return join.proceed();
} else {
// add joinpoint to list pending print
m_pendingPrints.add(join);
m_nestingDepth++;
// time joinpoint execution
long start = System.nanoTime();
Object result = null;
Throwable thrown = null;
try {
result = join.proceed();
} catch (Throwable t) {
thrown = t;
} finally {
// adjust depths
m_nestingDepth--;
if (match) {
m_matchDepth--;
}
// remove joinpoint if still on pending list
// (will always be last in list)
boolean entered = true;
if (m_pendingPrints.size() > 0) {
m_pendingPrints.remove(m_pendingPrints.size()-1);
entered = false;
}
// check if execution time above cutoff
long time = System.nanoTime() - start;
if (time >= m_minimumNanoseconds || thrown != null) {
// print all unprinted "entering" lines
int count = m_pendingPrints.size();
for (int i = 0; i < count; i++) {
// print entering information for nesting call
// (nesting depth based on start of pendings)
indent(m_nestingDepth-count+i);
JoinPoint prior = (JoinPoint)m_pendingPrints.get(i);
System.out.print('>');
printFullMethod(prior);
System.out.println();
}
// clear all pendings now that they're printed
m_pendingPrints.clear();
// print exiting information including time
indent();
System.out.print(entered ? '<' : '*');
printFullMethod(join);
System.out.print(" took ");
long tenthmillis = (time+50000)/100000;
System.out.print(tenthmillis / 10);
System.out.print('.');
System.out.print(tenthmillis % 10);
System.out.print(" ms.");
// append exception information
if (thrown != null) {
System.out.println(" threw " +
thrown.getClass().getName() +
": " + thrown.getMessage());
throw thrown;
} else {
System.out.println();
}
}
}
return result;
}
}
}
|
基本的な原則は、前回の記事と同じですが、このコードでは少し、おまけを追加しています。nanoTime()を使うということの他に、3つのコンフィギュレーション・パラメーターを、オプションとしてアスペクト定義に追加しています。これらのパラメーターによって、下記を制御します。
- トレース出力に含まれるべきメソッド・コールに対する最小測定時間
- 出力に含まれるべき最大ネスト深さ
- このメソッドによって（直接、間接に）呼ばれたコールのみが出力に含まれるように、トレースをオンするために使われるトリガー・メソッド
追加されたコンストラクター・コードは、AspectWerkz 2.0が定義するシグニチャーを使って、アスペクトに対する全パラメーター定義を含むコンテキスト情報にアクセスします。こうしたパラメーターが、XMLコンフィギュレーション・ファイルの中でどのように定義されるかについては、実際に使われるところで説明します。
実際のtrace()メソッドの最初で、私はトリガー・メソッド名とクラスの一致をテストする論理を追加しています。この論理は、コールが出力されないことが分かっている場合（トリガー・メソッドが現在のコール・ネストに無いか、あるいは対象とすべきコールに対してネストの奥深く入りすぎている）には、タイミング測定なしにjoinpointメソッド・コールを単に直接実行します。また、基本的な時間測定コードには、スロー可能な（throwable）処理も追加しています。そのためメソッドが、通常の戻りではなくスローを通して終了する場合には、投げられた基本情報がトレースの中に含まれるようになっています。
最後に、トレース出力の書式を変更し、少し読みやすくしています。段付けに単にスペースを使う代わりに、このコードではスペースとハイフンを交互に使い、メソッド・コールがネストの一番深いところにある場合には、ネスト・レベルからの出ることを示すために使われる< 記号ではなく、前にアスタリスクを付けて出力されます。
改善された、新しいパフォーマンス・トレース・アスペクト（リスト4）の準備ができたら、必要なのは、私のアスペクト顕微鏡下での調査の対象となる、ターゲット・アプリケーションだけです。私はアプリケーションとして、Apache AxisのWebサービス・フレームワークを選びました。サーバー・コードで様々なものを複雑にしないように、クライアント・アプリケーションを実行させます。私の本業はWebサービスなので、私にとってAxisを選ぶのは自然に思えます。私はこれまで少なくとも2、3週間はAxisコードをいじっているので、その構造には慣れています。ただし、複雑になりがちなAxisコードを初めて追跡しようとした時の苦しさも、よく覚えています。
Webサービスを扱っていない読者のために、概要を説明しましょう。Axisは、Java Webサービスに対するJAX-RPC標準の実装です。Axisはクライアント・アプリケーション（XMLメッセージの形でリクエストを生成します）とサーバー・アプリケーション（受信したリクエストに対してXMLレスポンス・メッセージを生成します）の両方をサポートしており、両者はAxisコードの大部分を共有しています。Webサービスのメッセージ交換の性質から言って、このフレームワークが高位レベルでどのように動作するかは明らかでしょう。クライアント側では、次のように要約できます。リクエストに対するデータをユーザー・コードから受け付け、そのデータをコンフィギュレーション情報と組み合わせてリクエストXMLを生成し、リクエストを送信してレスポンスを待ち、レスポンスからデータを抽出し、最後にそのデータをユーザー・コードに渡すのです。このプロセスの詳細、つまりAxisフレームワークの中で実際にどのように行われるかという詳細が、非常に分かりにくいのです。
私は、以前Webサービスのパフォーマンス・テストに使った、既存のAxisクライアント・アプリケーションを持っています（参考文献にリンクがあります）。そこでこのコラムでは、パフォーマンス・トレース・アスペクトを、このクライアント・アプリケーションに対して使うことにします。また、クライアントがレスポンスを生成できるように、クライアントに対応したAxisサーバー・アプリケーションも実行しますが、パフォーマンス・トレースにはそれを含めません。このアプリケーションの本来の目的は、サーバー上にある地震のデータベースから情報を検索することです。
Axis実行で最初に見たいものは、実行に一番長く時間がかかるのはどのコード部分かを示すような、基本的な時間分布です（もちろん、こうした部分につながるパスも同時に見たいですが）。これを実現するために、アスペクト用のコンフィギュレーションとして、アプリケーション・コードとAxisコードの両方の中でのメソッド・コールを全て捕捉すること、ただし最大ネスト深さ7までとするようにアスペクトに伝えるコンフィギュレーションを使います。こうすることで、詳細に圧倒されないようにするのです。リスト5は、私が使おうとしているAspectWerkzコンフィギュレーション・ファイルを示しています。
リスト5. コンフィギュレーションを少し覗く
<aspectwerkz>
<system id="AspectWerkzExample">
<package name="com.sosnoski.aspectwerkz">
<aspect class="TraceAspect">
<pointcut name="traceexecution">
execution(* org.apache.axis..*(..)) || execution(* com.sosnoski.seismic..*(..))
</pointcut>
<advice name="trace" type="around" bind-to="traceexecution"/>
<param name="maximum-depth" value="7"/>
</aspect>
</package>
</system>
</aspectwerkz>
|
リスト5のコンフィギュレーションの大部分は、前回のコラムの読者にはおなじみのはずです。前回のコンフィギュレーションとの主な違いは、今回の方がアスペクト用のポイントカット定義に複雑な表現を使っていること、そして最大ネスト深さを定義するためのパラメーター値を追加している、という点です。前回のコンフィギュレーションでは、pointcut要素の属性を使って表現を定義していました。要素の内容として表現を使う場合には、長い表現の方が容易なのです。AspectWerkzでは、どちらの形式でも同じように使用できます。このポイントカット表現は、org.apache.axis階層構造とcom.sosnoski.seismic階層構造の両パッケージの全クラスにある、全メソッド・コールを含めたい、と言っているのです。
Axisを使った私のテストでは、通常は複数パス（リクエストとリスポンスのやり取り）でコードを実行します。つまり最初のパスで初期化を処理し、その後のパスではフルスピードで実行するのです。パフォーマンス・トレース・アスペクトを使った私のテストでは、単に2つのパスのみを使い、2回目のパスの出力のみを示すことにします。リスト6は、このプログラムを、リスト5のコンフィギュレーションを使ってAspectWerkzで実行した場合の出力です。ここで注意して欲しいのですが、時間測定にはnanoTime()を使っていますが、出力した時の数字を適切に制限するために、全ての時間値はミリ秒に変換されています。
リスト6. パフォーマンス・トレースを少し覗く
Running query for date range from 2002-04-02 13:12:53 to 2002-12-15 04:08:40,
longitude range from 40.71031 to 160.91571,
latitude range from -70.6799 to 22.293274,
->com.sosnoski.seismic.axislit.AxisDocLitClient.runQuery
- >com.sosnoski.seismic.axislit.SeismicBindingStub.matchQuakes
- ->org.apache.axis.client.Call.invoke
- - >org.apache.axis.client.Call.invoke
- - ->org.apache.axis.client.Call.invoke
- - - *org.apache.axis.client.Call.invoke took 591.4 ms.
- - - *org.apache.axis.message.RPCElement.getParams took 1447.0 ms.
- - -<org.apache.axis.client.Call.invoke took 2042.0 ms.
- - <org.apache.axis.client.Call.invoke took 2042.9 ms.
- -<org.apache.axis.client.Call.invoke took 2043.1 ms.
- ->org.apache.axis.client.Stub.extractAttachments
- - >org.apache.axis.Message.getAttachments
- - ->org.apache.axis.attachments.AttachmentsImpl.getAttachmentCount
- - - *org.apache.axis.SOAPPart.saveChanges took 155.7 ms.
- - -<org.apache.axis.attachments.AttachmentsImpl.getAttachmentCount took 157.5 ms.
- - <org.apache.axis.Message.getAttachments took 157.7 ms.
- -<org.apache.axis.client.Stub.extractAttachments took 157.9 ms.
- <com.sosnoski.seismic.axislit.SeismicBindingStub.matchQuakes took 2202.4 ms.
-<com.sosnoski.seismic.axislit.AxisDocLitClient.runQuery took 2202.9 ms.
Results from query:
Seismic region New Zealand Region has 1 regions and 2 matching quakes
Seismic region Bismarck and Solomon Islands has 4 regions and 30 matching quakes
Seismic region New Guinea has 9 regions and 55 matching quakes
Seismic region Caroline Islands Area has 2 regions and 8 matching quakes
Seismic region Guan to Japan has 2 regions and 10 matching quakes
Seismic region Taiwan Area has 1 regions and 2 matching quakes
Seismic region Philippine Islands has 5 regions and 22 matching quakes
Seismic region Bornea - Sulawesi has 10 regions and 37 matching quakes
Seismic region Sunda Arc has 12 regions and 49 matching quakes
Seismic region Myanmar and Southeast Asia has 1 regions and 2 matching quakes
Seismic region India - Xizand - Sichuan - Yunnan has 1 regions and 2 matching quakes
Seismic region Indian Ocean has 9 regions and 27 matching quakes
Seismic region Africa has 3 regions and 3 matching quakes
Seismic region Macquarie Loop has 1 regions and 2 matching quakes
Seismic region Andaman Islands to Sumatera has 4 regions and 14 matching quakes
-*com.sosnoski.seismic.axislit.AxisDocLitClient.summarize took 1.7 ms.
Result match count 265 in 2203 ms.
|
私のクライアント・テスト・プログラムは、結果をコンソールに出力します。そのためリスト6では、パフォーマンス・トレース情報と混じった形で結果が出力されます。クライアント・プログラムの出力を無視してトレース情報を見ると、時間がどこで費やされているのか、すぐに分かります。つまり合計時間の90%以上がorg.apache.axis.client.Call.invoke()メソッドで費やされているのです（リスト6で、太字で示されたトレース出力です）。同じ名前を持つ別メソッドへのコール（あるいは、同じメソッドへの再帰的コールなのか、このトレースからは判定できません）には、その時間の30%以下の時間しか使われていない一方で、実質的に残りの時間の全てがorg.apache.axis.message.RPCElement.getParams()メソッドへのコールに使われています。
リスト6の最後の行に示したリクエストに対する実行時間の合計（2203ミリ秒）を、AspectWerkzを通さないでリクエストを実行した場合のタイミングとを比較すると、監視することによってプログラムにどの位のオーバーヘッドを追加しているかの感覚をつかむことができます。この場合では、約2倍になっています。つまり、直接プログラムを実行した場合は、通常は1000から1100ミリ秒の範囲です。
アスペクトを適用すると、なぜプログラムの実行速度が半分になってしまうのでしょう。追加されたオーバーヘッドには、2つの別々な要素があります。第1は、AspectWerkzによるバイトコード操作によって追加されるオーバーヘッドです。このバイトコード操作のおかげで、ターゲット・メソッドが呼ばれる時には必ずアスペクトが呼ばれるようになります。第2は、私の時間測定コードと、コンソールへのトレース出力によって追加されるオーバーヘッドです。
この2つの要素の影響を比較するには、trace()メソッド本体の中のreturn join.proceed(); 以外のものをコメントにし、メソッド・コール捕捉によるオーバーヘッドのみが追加されるようにします。そうしてみても、リスト6に示す完全出力の場合よりも10%速くなるだけであることが分かります。ですからこの場合では、オーバーヘッドの大部分は、このアスペクトへのコールによるものだと言うことが分かります。
このオーバーヘッドは、ポイントカット・メソッドに関して選択的にすれば、減らすことができます。例えば、単にフィールド値を返すだけの、些細なgetメソッドを捕捉するのを止めればよいのです。こうした些細なgetメソッドは、恐らくメソッド・コールの大部分を占めているため、これを無くすことによって、大幅にオーバーヘッドを削減できるはずです。残念ながらAxisコードでは、メソッド名を基にこの処理を行うための一貫した方法はありません。些細な操作にも複雑な操作にもget型の名前を使うという、標準Java言語のイディオムに従わざるを得ないためです。AspectWerkzでは、こうした些細なメソッドと、アスペクトを適用する際に少なくとも何らかの処理を行うメソッドとを、容易に区別することができるのですが、こうしたメソッドをポイントカットから排除するようにAspectWerkzに伝える方法がありません。ですから私は、ポイントカットの中のクラス数を減らすか、あるいは、ポイントカットから排除すべきメソッドを個別にリスト・アップしない限り、捕捉のオーバーヘッドから逃れられないのです。どちらの選択肢もあまり魅力的ではありません。ですから、このオーバーヘッドで我慢することにし、私の手法が通用しなくなるまで、有用な情報がどれくらい得られるかを調べることにします。
リスト6に戻ると、合計時間の90%以上がorg.apache.axis.client.Call.invoke()メソッドで使われています。より詳細なパフォーマンス・トレースのためには、このメソッドをターゲットとするのが自然なようです。そこで、リスト7のコンフィギュレーションを使って、より詳細なビューを得ることにします。
リスト7. コンフィギュレーションを掘り下げる
<aspectwerkz>
<system id="AspectWerkzExample">
<package name="com.sosnoski.aspectwerkz">
<aspect class="TraceAspect">
<pointcut name="traceexecution">
execution(* org.apache.axis..*(..)) || execution(* com.sosnoski.seismic..*(..))
</pointcut>
<advice name="trace" type="around" bind-to="traceexecution"/>
<param name="maximum-depth" value="5"/>
<param name="trigger-method" value="org.apache.axis.client.Call.invoke"/>
</aspect>
</package>
</system>
</aspectwerkz>
|
リスト7のコンフィギュレーションのポイントカット定義は前と同じですが、アスペクトに対するトリガー・メソッド・パラメーターを追加しており、最大ネスト深さを5にまで減らしています。リスト8は、このトレース・コンフィギュレーションで生成される出力を示しています（クライアント・プログラムの出力が無いことは、前と同じです）。
リスト8. レース出力を掘り下げる
>org.apache.axis.client.Call.invoke
>org.apache.axis.client.Call.invoke
->org.apache.axis.client.Call.invoke
- >org.apache.axis.client.Call.invoke
- ->org.apache.axis.MessageContext.setTargetService
- - *org.apache.axis.AxisEngine.getService took 14.9 ms.
- -<org.apache.axis.MessageContext.setTargetService took 16.7 ms.
- ->org.apache.axis.client.Transport.setupMessageContext
- - *org.apache.axis.transport.http.HTTPTransport.setupMessageContextImpl took 2.8 ms.
- -<org.apache.axis.client.Transport.setupMessageContext took 3.4 ms.
- ->org.apache.axis.message.MessageElement.output
- - *org.apache.axis.message.SOAPEnvelope.outputImpl took 5.8 ms.
- -<org.apache.axis.message.MessageElement.output took 6.5 ms.
- ->org.apache.axis.client.Call.invokeEngine
- - *org.apache.axis.client.AxisClient.invoke took 572.3 ms.
- -<org.apache.axis.client.Call.invokeEngine took 573.4 ms.
- >org.apache.axis.client.Call.invoke took 602.6 ms.
- >org.apache.axis.message.RPCElement.getParams
- ->org.apache.axis.message.RPCElement.deserialize
- - *org.apache.axis.message.MessageElement.publishToHandler took 1447.2 ms.
- -<org.apache.axis.message.RPCElement.deserialize took 1449.0 ms.
- <org.apache.axis.message.RPCElement.getParams took 1449.4 ms.
-<org.apache.axis.client.Call.invoke took 2054.9 ms.
<org.apache.axis.client.Call.invoke took 2057.1 ms.
<org.apache.axis.client.Call.invoke took 2057.4 ms.
|
このビューは、前のものよりも実行時間を詳細に示しています。これを見ると、org.apache.axis.client.Call.invoke()へのコールとして最も内側のものは、サーバーへのコールを含めたリクエスト処理をラップするコールであることが分かります。このコールは、返る前にサーバーが応答するのを待つ必要があります。明らかに、トレースで網羅されているものの外側で大量の処理が行われているのです（全てのサーバー・コードは、別のJVMの中で、AspectWerkz無しに実行しています）。クライアントを処理するための本当の負荷は、org.apache.axis.message.RPCElement.getParams()コールの中に現れており、その処理時間のほとんど全てが、org.apache.axis.message.MessageElement.publishToHandler()へのコールに費やされていることが分かります。
これをさらに深く掘り下げ、リスト8の出力の中で、クライアント処理の大部分が行われている部分として現れているメソッド、つまりorg.apache.axis.message.MessageElement.publishToHandler()メソッドに入り込むことにします。リスト9は、これを行うためのコンフィギュレーションを示しています。ここでは、もはやクライアント・コードは関心事項ではないので、ポイントカットから落としました。また、トレースに含まれるべき、メソッド・コールに対する最小時間も、0.4ミリ秒にまで下げました（ナノ秒で表現しています）。最後に、トレースをアクティブにするためのトリガー・メソッドを、問題のメソッドに変更しました。
リスト9. 第2のレベルにまで掘り下げたコンフィギュレーション
<aspectwerkz>
<system id="AspectWerkzExample">
<package name="com.sosnoski.aspectwerkz">
<aspect class="TraceAspect">
<pointcut name="traceexecution"
expression="execution(* org.apache.axis..*(..))"/>
<advice name="trace" type="around" bind-to="traceexecution"/>
<param name="minimum-time" value="400000"/>
<param name="maximum-depth" value="5"/>
<param name="trigger-method" value="org.apache.axis.message.MessageElement.publishToHandler"/>
</aspect>
</package>
</system>
</aspectwerkz>
|
リスト10は、リスト9のトレース・コンフィギュレーションで生成された出力のサンプルを示しています。完全な出力は非常に長く、繰り返しが多いため、ここではサンプルだけを見せています。この段階では、AxisのXMLメッセージ処理の詳細を見ていることになりますが、個々のメソッド・コールが費やす時間は大したものではありません。個々のコンポーネントを処理するために呼ばれるコールの数が非常に多く、それが積み重なっているのです。
リスト10. 第2レベルにまで掘り下げたトレース出力
>org.apache.axis.message.MessageElement.publishToHandler
>org.apache.axis.message.SAX2EventRecorder.replay
->org.apache.axis.encoding.DeserializationContext.startElement
- *org.apache.axis.message.RPCHandler.onStartChild took 0.7 ms.
- >org.apache.axis.encoding.ser.BeanDeserializer.startElement
- ->org.apache.axis.encoding.DeserializerImpl.startElement
- - *org.apache.axis.encoding.ser.BeanDeserializer.onStartElement took 12.8 ms.
- -<org.apache.axis.encoding.DeserializerImpl.startElement took 13.1 ms.
- <org.apache.axis.encoding.ser.BeanDeserializer.startElement took 13.1 ms.
-<org.apache.axis.encoding.DeserializationContext.startElement took 15.9 ms.
->org.apache.axis.encoding.DeserializationContext.startElement
- *org.apache.axis.encoding.ser.BeanDeserializer.onStartChild took 0.6 ms.
-<org.apache.axis.encoding.DeserializationContext.startElement took 1.0 ms.
-*org.apache.axis.encoding.DeserializationContext.startElement took 0.6 ms.
-*org.apache.axis.encoding.DeserializationContext.endElement took 0.5 ms.
->org.apache.axis.encoding.DeserializationContext.startElement
- *org.apache.axis.encoding.ser.BeanDeserializer.onStartChild took 0.5 ms.
-<org.apache.axis.encoding.DeserializationContext.startElement took 0.9 ms.
->org.apache.axis.encoding.DeserializationContext.startElement
- >org.apache.axis.encoding.ser.BeanDeserializer.onStartChild
- -*org.apache.axis.encoding.DeserializationContext.getTypeFromAttributes took 1.3 ms.
- <org.apache.axis.encoding.ser.BeanDeserializer.onStartChild took 1.9 ms.
-<org.apache.axis.encoding.DeserializationContext.startElement took 2.5 ms.
-*org.apache.axis.encoding.DeserializationContext.endElement took 0.6 ms.
->org.apache.axis.encoding.DeserializationContext.startElement
- *org.apache.axis.encoding.ser.BeanDeserializer.onStartChild took 0.4 ms.
-<org.apache.axis.encoding.DeserializationContext.startElement took 0.8 ms.
->org.apache.axis.encoding.DeserializationContext.startElement
- >org.apache.axis.encoding.ser.BeanDeserializer.startElement
- ->org.apache.axis.encoding.DeserializerImpl.startElement
- - *org.apache.axis.encoding.ser.BeanDeserializer.onStartElement took 121.8 ms.
- -<org.apache.axis.encoding.DeserializerImpl.startElement took 123.3 ms.
- <org.apache.axis.encoding.ser.BeanDeserializer.startElement took 123.3 ms.
-<org.apache.axis.encoding.DeserializationContext.startElement took 123.9 ms.
->org.apache.axis.encoding.DeserializationContext.endElement
- *org.apache.axis.encoding.DeserializerImpl.endElement took 0.5 ms.
-<org.apache.axis.encoding.DeserializationContext.endElement took 0.8 ms.
...
|
リスト10は、このパフォーマンス・トレース・アスペクトでどこまでが可能か、その限界を示しています。アプリケーション実行において大きく時間を食う要素を素早く知るためには便利ですが、具体的にどのコードの実行が遅く、改善の余地があるかどうかを切り分けるには、あまり便利ではありません。ただし後者の問題に対しては、通常の実行プロファイラーで非常にうまく対応できることなので、何の役にも立たないということにはなりません。パフォーマンス・トレースも実行プロファイラーも、アプリケーションのパフォーマンスの解析や改善のためには、非常に便利なツールなのです。
このコラムでは、トレース型のアスペクトによって、プログラムの実行に関する有用な情報が得られることを示しました。これらのアスペクトは、プログラム・コードに埋め込まれたロギング・ステートメントを置き換えるのでしょうか。私の見方としては、完全に置き換えることはないと思います。ロギングというのは、開発者やユーザーにとって関心のある、（ポイントカットが定義できない）メソッドの論理内部でのみアクセスされるような、特定の情報を記録するために使われる場合が多いからです。しかしこの情報は、パフォーマンス上の理由からロギングを使用不可にした場合には、生成されないかも知れません。ところが、このコラムで解析したAxisコードには、こうした特定な情報を提供する多くのロギング・ステートメントが含まれているのです。
他のタイプのロギング・ステートメントは、単純なメソッド・エントリーや終了(exit)の情報から構成されています。これらを、実行時にアクティブになる外部アスペクトと置き換えるのは容易なことです。このアスペクトが埋め込みのロギング・コードと同じロギング・フレームワークを使うようにし、出力を合成してプログラム実行のビューも同時に見えるようにすることができます。このタイプのアスペクトについては書きませんが、この手法をアプリケーションの中でどう使うかについては、このコラム・シリーズから理解できるのではないかと思います。
次回は、ASMバイトコード操作のフレームワークを見て行きます。ASMについては、JavassistやBCELフレームワークに代わるものとして、クラスワーキングに関する以前の記事でとりあげました。ASMは驚くようなパフォーマンス性能を持っています。そこでJavassistとBCELのために使ったものと同じ例をASM用に書き直しながら、パフォーマンスと使いやすさの両面から見て行くことにします。
| 内容 | ファイル名 | サイズ | ダウンロード形式 |
|---|---|---|---|
| ij-cwt04055-code.zip | ij-cwt04055-code.zip | 9KB | FTP |
- Dennis Sosnoskiによる、クラスワーキング・ツールキット・シリーズの全記事を読んでください（日本語に翻訳されていない記事もあります）。
- AspectWerkzについて詳しく知るためには、このプロジェクトのWebサイトを見てください。豊富なドキュメンテーションや、様々な記事へのリンクが網羅されています。
- Nicholas Lesieckiによるアスペクト指向プログラミングで、モジュール性を改善する（developerWorks, 2002年1月）を読んで、Java言語用のAspectJアスペクト指向エクステンションについて学んでください。
- Filippo DiotaleviによるAOPを使いコントラクトを実施する（developerWorks, 2004年7月）を読んで、コンポーネント間のアグリーメントのバインディングにとって、AOPがどれほど強力かを学んでください。
- コンポーネントに柔軟性がなくて困っているのであれば、Andrew GloverによるAOPが密結合の憂うつさを取り除く（developerWorks, 2004年2月）が良いヒントになるかも知れません。
- 既存のシステムを理解し、維持する上でAOPがどのように役立つかを、Abhijit BelapurkarがレガシーJavaアプリケーションの保守にAOPを使用する（developerWorks, 2004年3月）の中で解説しています。
- Gary PolliceによるA look at aspect-oriented programming（developerWorks, 2004年1月）はAOPの詳細以上の話題、つまりソフトウェア開発プロセスにもたらす影響やAOPが直面する困難などについて議論しています。
- AOPに関して既に知っており、基本以上のことを望むのであれば、6人のAOPエキスパートが執筆するAOP@Workシリーズを調べてみてください。
-
Apache Axisフレームワークは、広く使われているJAX-RPC Java Webサービス標準のオープンソース実装を提供しています。
- この記事の著者によるWeb Service Performanceの比較を見てください。様々なツールキットやスタイルのパフォーマンスを、他のWebサービス・ツールキットとの比較と、Java RMIとの比較の両方の面から解説しています。
- この記事の著者のDennis Sosnoskiによる、Javaプログラミング・ダイナミックス・シリーズの全記事を読んで、Javaのクラス構造、リフレクション、クラスワーキングなどを知るツアーに出かけてください（日本語に翻訳されていない記事もあります）。
-
developerWorksのJava technologyゾーンには、Java技術に関する資料が他にも豊富に用意されています。技術的なドキュメンテーションや、ハウツー記事、教育資料、ダウンロード、製品情報など、様々な情報を得ることができます。
-
New to Java technologyには、Javaプログラミングを始めるための助けとなる最新情報が用意されていますので、ご覧ください。
-
developerWorks blogsに参加して、developerWorksコミュニティーに加わってください。
- Developer Bookstoreには、Java関連の書籍をはじめ、広範な話題を網羅した技術書が豊富に取り揃えられていますので、ぜひご利用ください。
Dennis Sosnoskiはシアトル地域にあるJava技術のコンサルティング会社、Sosnoski Software Solutions, Inc.の創立者で、主席コンサルタントでもあり、またXMLおよびWebサービスのトレーニングとコンサルティングの専門家でもあります。彼のプロとしてのソフトウェア開発経験は30年以上に渡り、ここ数年はサーバー側XMLやJava技術に注力しています。全米各地で行われる会議では頻繁に講演を行っています。また、Javaクラスワーキング技術を利用して構築された、オープンソースのJiBX XML Data Bindingフレームワーク開発の中心的開発者でもあります。
タグ
スライダーバーを使用することで、より多く（少なく）タグを表示します。
人気のタグは、この特定のコンテンツ・ゾーン（例えば、Java テクノロジー、Linux や WebSphere など）に対するトップのタグを表示します。
マイ・タグは、この特定のコンテンツ・ゾーン（例えば、Java テクノロジー、Linux や WebSphere など）に対するお客様ご自身のタグを表示します。
記事の人気タグ |
記事のマイ・タグタグ・リストへスキップ
記事の人気タグ |
記事のマイ・タグ