2014/07/30

XPages Toolbox を使ってみる - バックエンドプロファイラー編

今回は、左から3つ目のタブにある「Backend Profiler」(バックエンドプロファイラー)についての説明になります。
操作方法は簡単です。
これからプロファイリングを始めたいときに、「Start Profiler」ボタンをクリックします。
その後、プロファイリング対象のアプリケーションを実際操作し、プロファイリング完了と思った時点で「Stop Profiler」のボタンを押します。すると、その下のビューに結果が表示されます。
また、プロファイリングが終了して結果の情報が不要になった場合に、「Remove All Documents」をクリックし、「Refresh」ボタンをクリックするとこれまでのプロファイリング結果をすべてクリアし、次のプロファイリングに備えます。

表示される結果ですが、このバックエンドプロファイラーで何がわかるかというと、XPage を操作している間に使われたバックエンドNotesクラスの
  • クラス
  • メソッド
  • 操作(Getなど)
  • コール数
  • 時間(ミリ秒)
が分かるようになっています。
上記の例では、文書(Document)のComputeWithFormメソッドで「781」ミリ秒使用したという結果が出ています。
実は今回プロファイリングしたこのXPage、ページを表示する前に、計算結果フィールドだけで約380程度のフィールドをフォームのフィールドにバインディングして「フォーム検証の実行」を指定し、初期値としてノーツのフォーム上のフィールドの省略値をそのまま計算して求めるという設定にしています。

計算結果フィールドの省略値として、ユーザー名を取得して、漢字アドレス帳から日本語名、所属部署名などをルックアップするなどページを表示する前にフィールドに値をセットする必要があるのですが、380フィールドで1秒もかからないのがわかったので(実際の経過時間は「2125」ミリ秒、約2秒)、まずは正常なパフォーマンスが得られるのではないかと推測します。

ひとつの XPage をプロファイルする際でも、部分更新(パーシャルリフレッシュ)が発生するとひとつの文書に出力するようです。

このように、Notesバックエンドクラスに対して、パフォーマンスに影響がでそうな処理(例えば、ビューを参照してループするなど)に対して、それぞれのメソッドに対して何度コールしどれぐらいの時間を消費したかを把握するのに便利なツールといえます。



2014/07/24

XPages Toolbox を使ってみる - コードプロファイリング編

今回は、みなさんが書いたサーバーサイド JavaScript のプロファイリングです。プロファリング手順に関しては、前回までの方法とまったく同じです。

自分の書いたサーバーサイド JavaScript に次の関数を追加することで、プロファイリング可能です。


今回、下のコードに対して(凄く簡単なスクリプトで申し訳ありません)プロファイリングしたい場合、
var d = getComponent("dialog1");
viewScope.put("SagyoTantoSelected","first");
d.show();

__profile() 関数を下のように追加します。
見にくいかもしれませんが、profile の前の「__」はアンダースコアを2つ続けます。
__profile("mycode","p1"){
var d = getComponent("dialog1");
viewScope.put("SagyoTantoSelected","first");
d.show();
}
ここで指定した「mycode」や「p1」は任意です。判別しやすい名前をつければ OK です。
 結果は上の画面のように出てきます。
Dojoダイアログをモーダル表示する処理で 16 ミリ秒使用したことがわかります。

この __profile() 関数の中に、別の __profile() として階層的に指定することも可能です。
バッチ処理的な SSJS で処理時間が気になるときには、このプロファイル関数を使用するとパフォーマンス改善の糸口が見えてくるかもしれませんね。

今回はこれで終了ですが、 次回はバックエンドプロファイラーを取り上げます。

2014/07/18

XPages Toolbox を使ってみる - CPU プロファイリング編

前回から始まった 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タイムを計測する方法を紹介したいと考えています。お楽しみに。





2014/07/15

XPages Toolbox を使ってみる - インストール編

OpenNTF Essentials の中に、「XPages Toolbox」というプロジェクトがあり、かねてから気になっていたんですが、触る機会がないまま放置していました。この Toolbox を使うと、XPages アプリケーションを動かしいる際の、CPU やヒープのダンプを取ったり、バックエンドの呼び出された回数を見たり、アプリケーションのパフォーマンスを調査する上で非常に役立つツールです。

XPages Toolbox を導入するとセキュリティ面で問題が発生するため、決して本番環境では使わないでくださいとの注意もされています。

プロジェクトの詳細をみると、要件に Notes/Domino 8.5.3 と記述されているので、9.0x では動かないのかなと思っていたのもあり、手を出していませんでした。
最近ふと Twitter を追っていくと Mastering XPages 2nd Edition の著者でもある方の 9.01 でも動きますというツィートに触発されて触ってみることにしました。

実際プロファイリングを行なうとわかりますが、自分が作成したアプリケーションの一連の処理を計測するのに向いていますが、開発サーバーで複数のア プリケーションを同時動かした中でのプロファイリングにはあまり向いていませんので、あくまで開発が終了した際のパフォーマンス検証という使い方が最もふ さわしいと感じました。

計測に当たっては、Windows OS の場合には、ネイティブなプロファイリングが可能ですが、他 OS は JVM 経由のプロファイリングになるため、多少誤差が生じるという注意書きもあります。

インストール関連は、他の方のブログやwikiに紹介されていますが、改めて私の方でも取り上げたいと思います。
今回私が使用するのは「XPages Toolkit 1.2」というバージョンです。
環境は自分のデスクトップ PC (VM) に Windows 32 bit 版のDomino サーバー 9.01 をたてています。

OpenNTF のプロジェクトページから、最新モジュール v1.2 をダウンロードします。
ダウンロードすると次のものが入っています。
赤枠で囲ったものが今回使用するものです。
ステップは以下の通りです。
  • XPagesProfilerAgent.jar
この jar ファイルを次の Domino サーバー上のディレクトリーへ配置します。
 <Domono実行ディレクトリー>¥xsp
例:C:\IBM\Domino\xsp
  • XspProfilerOptionsFile.txt
このテキストファイルを Domino サーバー上の実行ディレクトリー直下へ配置します。
例: C:\IBM\Domino
続いて、このテキストファイルに書かれている行を編集します。ここには、上記で配置した jar ファイルの場所を指定します。
例: -javaagent:c:/IBM/Domino/xsp/XPagesProfilerAgent.jar
  • java.policy ファイルへの行追加
Domino サーバー上の次のディレクトリーにある「java.policy」というファイルに次の行を追加します。
<Domino実行ディレクトリー>¥jvm¥lib¥security

追加する行は以下のとおりです。
grant codeBase "xspnsf://server:0/xpagestoolbox.nsf/-" {
    permission java.security.AllPermission;
};
  • notes.ini の編集
Domino サーバーの notes.ini に次の行を追加します。これは、上で説明した XspProfilerOptionsFile.txt を配置した場所を指定するパラメーターになります。
JavaOptionsFile=C:\IBM\Domino\XspProfilerOptionsFile.txt
  • XPagesToolbox.nsf
Domino サーバーのデータディレクトリーの直下にこのデータベースを配置します。(直下でないサブフォルダに配置したい場合は、java.policy で指定した場所を変更すれば良いらしいのですが、検証していません。)
この NSF では、Domino サーバー上で XPages を動作させる必要がありますので、適切な ID で署名します。テスト環境なので、Administrator の ID が良いでしょう。

これで、準備が整いました。
Domino サーバーを再始動します。
コンソール上を注意深く見ていただき、

*** Activating IBM XPages profiler agent

という表示が見られれば正常に動作を始めていることになります。

ブラウザより、「XPages Tookbox」データベースへアクセスし、次のページが表示されればすべての準備が完了です。
例:http://localhost/xpagestoolbox.nsf


次回は、実際のプロファイリングの方法をご紹介します。