^PROFILE を使用したルーチン・パフォーマンスの監視

^PROFILE ユーティリティは、プログラマがアプリケーションのルーチンおよびクラスのパフォーマンスを分析する際に利用できます。このタスクは、以下のように 2 フェーズ構成で実行されます。

データを収集し、ルーチン・レベルで並べ替え、最も “機能” しているルーチンを特定できます。
詳細レベルでデータ (サブルーチン、プロシージャ、および個別の行) の収集および表示が必要なルーチンを選択して、パフォーマンス上の問題が疑われる個別のルーチンへの “ドリル・ダウン” を可能にします。

既定の ^PROFILE は、最大で 5000 までのルーチンのメトリックを取得し、最大数のルーチンに使用できる十分なメモリがない場合は、メトリックの取得開始前に情報メッセージを表示してから、可能な限り多数のルーチンのメトリックを取得します。

監視するルーチンと収集するメトリックを選択した後に、領域が Caché で実行されるすべてのメトリックの収集には不十分な場合、このユーティリティによって、この収集の監視に必要なメモリのページ数と使用可能なページ数に関するメッセージが表示されます。

この章は、以下のセクションで構成されます。

^PROFILE の使用法

%SYS ネームスペースから (^PROFILE) ユーティリティを起動します。

%SYS>do ^PROFILE

データ収集の開始を求められたら、Enter を押します。

Note:

応答 (Yes および No 以外) を求められた場合は、「?」を入力してヘルプを表示できます。

既定では、プロファイルによってルーチンおよび以下のメトリックの番号付きリストが表示されます。初期設定の場合、このリストは RtnLine メトリックを基準にして並べ替えられます。

列タイトル (メトリック)	説明
RtnLine	実行されたコードのルーチン行数。既定では、実行された全行数に対するパーセント値で表示されます。
Time	ルーチンの実行に要した時間。既定では、すべてのルーチンの実行の合計所要時間に対するパーセント値で表示されます。
CPU	ルーチンの実行に要した CPU 時間。既定では、すべてのルーチンの実行の合計 CPU 時間に対するパーセント値でエントリが表示されます。
RtnLoad	ルーチンがロードされた回数。既定では、すべてのルーチンのロードに対するパーセント値でエントリが表示されます。
GloRef	ルーチンのグローバル参照数。既定では、すべてのルーチンのグローバル参照数に対するパーセント値でエントリが表示されます。
GloSet	ルーチンのグローバル SET 数。既定では、すべてのルーチンのグローバル SET 数に対するパーセント値でエントリが表示されます。

ルーチン名 (INT または MVI ファイル)、および実行されるネームスペースは、エントリの 2 行目に表示されます。

ターミナルに表示された指示に従います。

プロファイル・レベルでルーチンのリストが表示される場合は、以下のいずれかを指定できます。

オプション	説明
#	詳細なプロファイル・レベルのデータ収集が指定された行 (複数可) を示すフラグを指定します。 Note: 表示されるページのそれぞれに、個別の行数 (#)、コンマで区切られたリスト (#,#,#)、範囲 (#-#)、または組み合わせ (#-#,#,#-#,#) を入力できます。いずれかのページでルーチンを選択した後は、前後のページに移動して別のルーチンを選択できます。分析対象にするすべてのルーチンを選択したら、Q を入力して、詳細レベルのプロファイル収集を開始します。
B	リストの前のページを表示します。
E	表示されたメトリックのコレクションをエクスポートします。
N	リストの次のページを表示します。
O	別のメトリックを基準にしてページを並べ替えます (選択したメトリックが最初の列に表示されます)。
Q	^PROFILE ユーティリティを終了します。 Note: 分析対象のルーチンを示すフラグを指定した場合は、このオプションを指定することでサブルーチン・レベルおよび行レベルのメトリックを収集するか、終了するかを選択できます。
R	最新のメトリックでリストを更新します。
X	選択したルーチンのすべて (別のページで選択したルーチンも含む) のフラグをクリアし、メトリックの収集を更新します。

詳細プロファイリング・レベルでルーチンのリストが表示される場合は、以下のいずれかを指定できます。

オプション	説明
#	詳細に分析する必要があるルーチンの行番号。Enter を押すと、選択したルーチンのサブルーチン・ラベルが表示されます。
B	リストの前のページを表示します。
N	リストの次のページを表示します。
O	別のメトリックを基準にしてページを並べ替えます (選択したメトリックが最初の列に表示されます)。
Q	^PROFILE ユーティリティを終了します。
R	最新のメトリックでリストを更新します。

サブルーチン・ラベル (および各ラベルのメトリック) のリストが表示される場合は、以下のいずれかを指定できます。

オプション	説明
#	詳細に分析する必要があるサブルーチン・ラベルの行番号 (コード内)。Enter を押すと、指定したラベルのコードが表示されます。
B	リストの前のページを表示します。
L	サブルーチンの行レベル表示に切り替えます。
N	リストの次のページを表示します。
Q	リストを終了し、前のレベルに戻ります。
R	最新のメトリックでリストを更新します。 Note: リストに Unknown が表示された場合は、R を入力します。

コードの行が表示されると、次の操作を指定するように求められます。使用できるオプションは以下のとおりです。

オプション	説明
#	詳細に分析する必要があるコード内の行番号。Enter を押すと、指定したラベルのコードが表示されます。
B	リストの前のページを表示します。
C	コードの表示をソース・コードと中間 (INT/MVI) コード間で切り替えます。
M	ページのマージンまたは長さを変更します。
N	リストの次のページを表示します。
O	別のメトリックを基準にしてページを並べ替えます。
Q	リストを終了し、前のレベルに戻ります。
R	最新のメトリックでリストを更新します。
S	ルーチンのサブルーチン・レベルの表示に切り替えます。

^PROFILE の例

以下は、ターミナルで ^PROFILE ユーティリティを (%SYS ネームスペースから) インタラクティブに実行する例です。

以下のコマンドを入力します｡
```
DO ^PROFILE
```

以下のメッセージが表示されます。

This routine will start a system-wide collection of data
on routine activity and then display the results. There
may be some overhead associated with this collection,
but it should not significantly impact the system.
 
Are you ready to start the collection?  Yes =>

メトリックの収集を開始するには Enter を押します。以下のようなメトリックが表示されます。

Waiting for initial data collection ...

      RtnLine     Time        CPU         RtnLoad     GloRef      GloSet
1.    38.02%      0.03%       10.49%      0.83%       0.05%       0.08%
      SYS.Database.1.INT (CACHESYS)
2.    21.00%      0.08%       49.97%      0.12%       68.73%      7.55%
      DocBook.chapter.CLS (DOCBOOK)
3.    19.68%      0.01%       11.55%      7.16%       28.17%      88.34%
      DocBook.para.CLS (DOCBOOK)
4.    10.93%      0.00%       1.98%       19.64%      0.00%       0.00%
      %cspParser.INT (CACHELIB)
5.    1.99%       0.00%       2.05%       5.14%       0.07%       0.00%
      DocBook.Renderer.CLS (DOCBOOK)
6.    1.75%       0.00%       2.53%       22.46%      0.00%       0.00%
      %CSP.TokenStream.1.INT (CACHELIB)
7.    1.05%       0.00%       1.50%       6.00%       0.69%       0.83%
      DocBook.listitem.CLS (DOCBOOK)
8.    0.84%       0.00%       0.00%       0.01%       0.17%       0.78%
      PROFILE.INT (CACHESYS)
9.    0.76%       0.00%       0.48%       7.91%       0.24%       0.88%
      %Library.GlobalCharacterStream.1.INT (CACHELIB)
10.   0.47%       0.00%       0.48%       4.78%       0.12%       0.00%
      DocBook.block.CLS (DOCBOOK)
11.   0.33%       0.00%       0.51%       1.22%       0.15%       0.13%
      Security.Resources.1.INT (CACHESYS)
Select routine(s) or '?' for more options  N =>

詳細に分析する必要があるルーチンにフラグを指定します。例えば、2-3,5,7,10 と入力してから N または B を入力すると、別のページを表示して、さらにルーチンの選択を追加できます。

分析対象にするすべてのルーチンを選択して、Q を入力すると、以下のようなメッセージが表示されます。

There are 5 routines selected for detailed profiling. You may now
end the routine level collection and start a detailed profiler collection.
 
WARNING !!
 
This will have each process on the system gather subroutine level and line
level activity on these routines. Note that this part of the collection may
have a significant effect on performance and should only be run in a test
or development instance of Cache.
 
Are you ready to start the detailed collection?  Yes =>

Enter を押すと、以下のようなページが表示されます。

Stopping the routine level Profile collection ...
 
Loading ^DocBook.chapter.1 in c:\intersystems\cache\mgr\docbook\
Loading ^DocBook.para.1 in c:\intersystems\cache\mgr\docbook\
Loading ^DocBook.Renderer.1 in c:\intersystems\cache\mgr\docbook\
Loading ^DocBook.listitem.1 in c:\intersystems\cache\mgr\docbook\
Loading ^DocBook.block.1 in c:\intersystems\cache\mgr\docbook\
 
Detail level Profile collection started.
 
    RtnLine     Routine Name  (Database)
1.  0%          DocBook.Renderer.CLS (DOCBOOK)
2.  0%          DocBook.block.CLS (DOCBOOK)
3.  0%          DocBook.chapter.CLS (DOCBOOK)
4.  0%          DocBook.para.CLS (DOCBOOK)
5.  0%          DocBook.listitem.CLS (DOCBOOK)
 
Select routine to see details or '?' for more options  R =>

分析対象のコードが含まれるルーチンを選択すると、以下のようなページが表示されます。

Line  RtnLine                 Code
1.    0          ;DocBook.chapter.1
2.    0          ;(C)InterSystems, generated for class DocBook.chapter.  Do NOT
3.    0          ;;0032F4FE18715E65;DocBook.chapter
4.    0          ;
5.    0         %1Check(id="",lockonly=0) public {
6.    0             Set exists=($select(id="":0,(+##class(DocBook.chapter).%OnDe
7.    0         %AcquireLock(%this,locktype="") public {
8.    0             Quit ..%LockId(($listget($zobjval(,0,,,,3))),$s($e(locktype)
9.    0         %BMEBuilt(bmeName)
10.   0             Set bmeName = "$chapter"
11.   0             Quit ''$d(^DocBook.blockI("$chapter"))
12.   0         %BindExport(%this,dev,Seen,RegisterOref,AllowedDepth,AllowedCapa
13.   0             i $d(Seen(""_%this)) q 1
14.   0             Set Seen(""_%this)=%this
15.   0             s sc = 1
16.   0             s proporef=$PROPERTY(%this,"book")
17.   0             s proporef=$PROPERTY(%this,"component")
18.   0             s proporef=$PROPERTY(%this,"container")
19.   0             d:RegisterOref InitObjVar^%SYS.BINDSRV(%this)
20.   0             i dev'="" s t=$io u dev i $s($P(dev,":",1)="|TRM|":$$debugPu
21.   0             i AllowedDepth>0 s AllowedDepth = AllowedDepth - 1
 
Routine DocBook.chapter.1 in DOCBOOK - '?' for options  N =>