前回から始まった XPages Toolbox シリーズの第2弾は、CPU のプロファイリングです。
XPagesToolbox.nsf をブラウザで表示したところで前回は終わりました。
このアプリケーションには「Home」以外に、
- CPU Profiler
- Backend Profiler
- Runtime Monitoring
- Session Dumps
- Periodic Snapshots
- Threads
- Logging
の7つのタブがあります。早速 CPU のプロファイリングのタブを開いてみましょう。
CPU タイムの計測
まずここで計測できるのは、CPU タイムになります。
一般的に CPU タイムは、CPU の負荷と言い換えれば分かりやすいかもしれません。処理演算によって使用される時間を計測して、どの処理が重いのかを計測するものです。ここで少し言葉の定義ですが、
- CPU タイム (CPU Time) は、スレッドが実行時に実際に消費した時間
- Wall タイム (Wall Time) は、スレッドにより消費された時間で、CPU タイムに加え、スリープや待ち時間を加えた時間
をいいます。
また、プロファイリングした結果のことをスナップショット(Snapshot)という言い方をしています。
上の画面にはいくつかボタンがありますのでその説明から。
ボタンの説明
- Start CPU Time Profiler:CPU Time のプロファイリング実行開始します
- Start Wall Time Profiler:Wall Time のプロファイリング実行開始します
- Stop Profiler:プロファイリングを終了し、プロファイリングの結果文書を作成します。(プロファイリングを開始していない場合は、グレイアウトしてクリックできません)
- Reset Profiler:プロファイリングで収集したデータはメモリー上に残っていますが、このボタンを押してメモリー上のデータを消去します
- Save Snapshot:プロファイリング継続中でも、今時点のスナップショットを作成します
- Delete Snapshots:プロファイリングの結果の文書をすべて削除します
プロファイリング操作
プロファイリングの操作は、以下のとおりで簡単です。
1. 「Start CPU Time Profiler」ボタンか「Start Wall Time Profiler」のいづれかをクリックして開始します。
ステータスは 「Started」に変われば、開始しています。
2. 次に実際のアプリケーションを動かします。動かす対象によって、1ページだけとか1ファンクションだけとか、一連の処理だとかによって、自分のプロファイリングしたい場所の開始から終了を動かしてみます。
3. アプリケーションの操作が終了したら、XPagesToolbox.nsf に戻ってきて、「Stop Profiler」ボタンを押し、プロファイリングを終了します。
スナップショットの見方
計測の開始から終了までは大した事はありませんが、プロファイリングの結果をどうみるかが大変です。できるだけ、分かりやすく説明したいと思いますが、見るものが違えば当然結果も違ってきますから、ここでは
Mastering XPages 2nd Edition で提供されているサンプルデータベースを使って説明します。
「Chp20Ed2.nsf」をブラウザから開くと、次のページが開きます。
赤い四角で囲ったリンクをクリックします。すると下のページが表示されるので、一番上の「Run CPU Intensive Task (clocking 'CPU Time')」ボタンを押します。
その後、処理がバックエンドで始まりますが、しばらく経過すると終了します。このボタンを押す前と押して処理が完了するまでをプロファイリングした結果は、私の環境では次のようになります。
スナップショット文書は、プロファイリング単位に日付時刻でカテゴライズされています。
さらに、「XPages Request」で呼び出した XPage (例では /Chp20Ed2.nsf/testCPUvsWallTime.xsp) ごとにカテゴライズされています。
時間はミリ秒でカウントされます。上の例では、「INVOKE_APPLICATION 5」のJSFフェーズで9秒かかかっていることがわかります。
私の手元にあるサンプルアプリケーション以外の実際のアプリケーション(新規XPage作成、単一のDomino文書にバインド、フィールド数約300)を開いた直後のものでは、次のような結果が出ました。
特に目立った数値はありませんが、実際のアプリケーションでは「XSP:Create view root」を最初に注目したほうが良いかもしれません。Create view root は XPage(ページ)に各コンポーネントを階層的にぶら下げてビュー(ページ)を作成するのですが、約300程度の入力コンポーネントや計算結果フィールドといった様々なコンポーネントをツリー構造としてページを構成するのに、31ミリ秒かかかったということになります。
もうひとつ、実際のアプリケーションで時間がかかると想定されるのは、「RENDER_RESPONSE 6」のフェーズです。これはフィールド数が多くなればなるほど値が大きくなるのが予想されます。
いずれにしても、ひとつのXPaegs リクエスト(ページからページまでの表示の間)に何秒という基準(たとえば3秒)を決めておいて合計の時間が超えているかを確認しながら、超えている場合には、詳細にドリルダウンしていくのが実際的ではないかと思います。
※失敗談より
プロファイリングを行い、プロファイリングを停止してスナップショットが作成されますが、次のプロファイリングを行なう前に必ず「Reset Profiler」をしてください。メモリー上に前回のデータが残っていますので、これをせずに続けてプロファイリングを行なうとスナップショットの数値が2倍、3倍となっていきますので注意してください。
その他のビュー
スナップショットの結果から特にCPU時間を取っているものだけを見る事ができるビューも用意されています。
「Hierarchical Dominators」というビューで、顕著なCPUタイムの消費を確認できます。これは、アプリケーションをずーっと動かしぱなしのプロファイリングをしたときに特に有効ではないかと思います。
その他、呼び出したカウント数、合計時間、時間がかかった順、時間÷カウント数で計算した平均時間別などのビューがあります。
一度確認してみてください。
次回は、自分の書いた SSJS コードに対しての CPUタイムを計測する方法を紹介したいと考えています。お楽しみに。