【IRIS】【計測関連】処理の動きを計測しよう (^%SYS.MONLBL)

本記事は、計測シリーズとして「^%SYS.MONLBL」を利用したデータ収集について解説します。

※この記事は下記の方向けになります。
  • 行(ライン)単位での処理速度を把握したい方
  • どの行が実行されているかを確認したい方
  • ディスクアクセスやメモリ使用状況を詳細に分析したい方

はじめに

^%SYS.MONLBL は、ObjectScript の処理を行単位で詳細に計測できるツールです。

ただし、実行時には多くの情報をサンプリングするため、システムに一定の負荷がかかり、処理速度が低下します。

そのため、本番環境で利用する際は影響範囲を十分に確認してください。
可能であれば検証環境での使用を推奨します。

計測開始

ターミナルを起動し、計測対象のネームスペースに切り替えます。

zn [計測対象のネームスペース]

計測準備

以下のコマンドを実行します。

d ^%SYS.MONLBL

コマンド実行後、警告メッセージが表示されます。
これは「パフォーマンスに影響が出る可能性がある」旨の注意喚起であり、通常は問題ありません。

【機械翻訳】
警告!
「line-by-line monitor」を起動すると、選択したルーチンおよびプロセスによって実行されるコードのすべての行の統計情報が収集されます。

これはシステムのパフォーマンスに大きな影響を与える可能性があるため、「テスト」システムで実行することをお勧めします。

「line-by-line monitor」は、選択した各ルーチンの各行の統計情報を追跡するために共有メモリも割り当てます。

これは既に割り当てられている汎用共有メモリから取得されるため、「*」ワイルドカードを使用して多数のルーチンを解析する場合は、この点を考慮する必要があります。

メモリ割り当ての問題によりモニターが起動しない場合は、システム構成で汎用メモリヒープ(gmheap)パラメータの値を増やす必要がある場合があります。

「2.) Memory Requirements」オプションを使用すると、(収集を開始せずに)収集に必要なメモリ量を確認できます。

■計測開始

「1.) Start Monitor」を選択して計測を開始します。

1.) Start Monitor
2.) Memory Requirements
 
Enter the number of your choice: 1

■計測対象のクラス・ルーチンの選択


対象となるルーチンを指定します(複数ルーチンの入力が可能)。
ワイルドカード(*)の使用が可能です。

Enter the number of your choice: 1
 
Enter routine names to be monitored on a line by line basis.
Patterns using '*' are allowed.
Enter '?L' to see a list of routines already selected.
Press 'Enter' to terminate input.
 
Routine Name: developer.Sample.*         (2 routines added to selection.)
Routine Name:

※.intファイル単位で計測されるため、「.*」を付けるのが一般的です。


■メトリックの選択

今回は、「4) Monitor All Metrics」を選択します。

Select Metrics to monitor
  1) Monitor Minimal Metrics
  2) Monitor Lines (Coverage)
  3) Monitor Global Metrics
  4) Monitor All Metrics
  5) Customize Monitor Metrics
 
Enter the number of your choice: <1> 4

※各項目の選択を後程解説します。


■測定対象のプロセスを選択

今回は、全プロセスを対象とするため、「1) Monitor All Processes」を選択します。

Select Processes to monitor
  1) Monitor All Processes
  2) Monitor Current Process Only
  3) Enter list of PIDs
 
Enter the number of your choice: <1> 1

テスト環境では他のプロセスが動かない想定なので、「全プロセス」を選択しておいた方が簡単です。


■モニタ起動開始

Enterキーでモニタを開始します。

Monitor started.
 
Press RETURN to continue ...

■カウンタのクリア

念のため、開始直後にカウンタをリセットしたいため、「3.) Clear Counters」を選択します。

Line-by-Line Monitor
 
1.) Stop Monitor
2.) Pause Monitor
3.) Clear Counters
4.) Report - Detail
5.) Report - Summary
6.) Report - Delimited (CSV) Output
7.) Report - Procedure Level
 
Enter the number of your choice: 3

別ターミナルでコマンド実行

別ターミナル、または同一ターミナルで対象処理を実行します。

■サンプルPG

今回は下記処理を実行します。

ClassMethod lineTest()
{
	s start = $zh
	
	s (key, ID) = ""
	, cnt = 0
	f { s key = $o(^developer.data.Defrag1I("idxBirth", key)) q:key=""
		f { s ID = $o(^developer.data.Defrag1I("idxBirth", key, ID)) q:ID=""
			s cnt = cnt + 1
			
			s data = ^developer.data.Defrag1D(ID)
			
			s $lg(,,,,,,,,,,patientId,漢字氏名,,,,,性別,生年月日) = data
			
			s 生年月日H = ..lineTestSub(生年月日)

			s ^Sample.data(patientId)=$lb(漢字氏名,性別,生年月日H)
			
			q:(cnt>100000)
		}
	}
	
	s time = $zh - start
	w !,$$$FormatText("件数:%1, 処理時間:%2", cnt, time)
}

ClassMethod lineTestSub(date As %String) As %Date
{
	s dateH = $zdt(date, 3)
	
	q dateH
}

実行します。

処理が完了したら、計測を終了しましょう。

計測終了とCSV出力

余計なデータ取得を防ぐため、まず一時停止してCSVファイルを出力します。

■一時停止

余計なデータ取得を防ぐため、まず一時停止します。
「2.) Pause Monitor」を選択します。

Line-by-Line Monitor
 
1.) Stop Monitor
2.) Pause Monitor
3.) Clear Counters
4.) Report - Detail
5.) Report - Summary
6.) Report - Delimited (CSV) Output
7.) Report - Procedure Level
 
Enter the number of your choice: 2

■結果の出力

計測結果をCSVで出力します。
「6.) Report – Delimited (CSV) Output」を選択します。

Line-by-Line Monitor
 
1.) Stop Monitor
2.) Resume Monitor
3.) Clear Counters
4.) Report - Detail
5.) Report - Summary
6.) Report - Delimited (CSV) Output
7.) Report - Procedure Level
 
Enter the number of your choice: 6

出力対象のクラス・ルーチンを選択します。

計測した全てのルーチンを対象とする場合は、「* or all」を選択してください。
特定のルーチンのみを出力する場合は、ルーチンの左にある番号を入力して下さい。

The following routines have been executed during the run,
and have detail statistics available for them.
1) developer.Sample.1
 
Enter list of routines, or * for all
Routine number (*=All)? *

出力先のディレクトリとファイル名を入力します。

The following routines have been executed during the run,
and have detail statistics available for them.
1) developer.Sample.1
 
Enter list of routines, or * for all
Routine number (*=All)? * - All
FileName: D:\Temp\csv\sample.csv

■戻る

CSVの出力が完了したら、Enterで戻ります。

Output written to D:\Temp\csv\sample.csv
 
Press RETURN to continue ...

■計測終了

計測を終了させるには、「1.) Stop Monitor」を選択します。

Line-by-Line Monitor
 
1.) Stop Monitor
2.) Resume Monitor
3.) Clear Counters
4.) Report - Detail
5.) Report - Summary
6.) Report - Delimited (CSV) Output
7.) Report - Procedure Level
 
Enter the number of your choice: 1

計測停止の意思を確認してくるので、「y」を入力します。

Stopping the line-by-line monitor will delete all of the data collected.
You should first save one or more of the Reports if you want to save the data.
 
Are you sure you want to stop the line-by-line monitor (y/n)? y

【機械翻訳】
行単位のモニターを停止すると、収集されたすべてのデータが削除されます。
データを保存する場合は、まず 1 つ以上のレポートを保存する必要があります。


■最初の画面に戻る

Enterをクリックして計測を修了します。

1.) Start Monitor
2.) Memory Requirements
 
Enter the number of your choice:

メトリックについて

出力されたファイルを確認します。

状況によって確認するメトリックは異なりますが、主に確認すべき項目は以下です。

メトリック説明
RtnLine行の実行回数
Time該当行の実行時間
TotalTime呼び出し先を含めた総時間
GloRefグローバル参照回数
GloSetグローバル更新回数

これらを確認することで、以下等を特定できます。

  • ボトルネックとなっている処理
  • 不要なループ
  • 無駄なグローバルアクセス

■実際に出力したCSVの一部

実行結果を確認すると、グローバルアクセスを行っている処理(Row=769)が、約14万回実行され、合計で約8.4秒を要していることが分かります。

1回あたりの処理時間はわずかですが、全体の処理時間が11.5秒であることを踏まえると、約73%をこの処理が占めていることになります。

この結果から、「ループ回数は適切か」「データ取得前に continue などで回避できないか」等々の改善案が考えられます。

このように、^%SYS.MONLBL を用いて処理を計測することで、各行の実行時間や無駄な処理を可視化でき、処理が適切かどうか、また改善が必要な場合の具体的な対策を検討しやすくなります。

メトリックの説明

各メトリックの説明と、「メトリック選択時」の各項目が対象としているメトリックの解説です。

メトリック選択時の項目

  1. Monitor Minimal Metrics
  2. Monitor Lines (Coverage)
  3. Monitor Global Metrics
  4. Monitor All Metrics
項目説明MinimalLinesGlobalAll
Routineルーチン名
Line実行行
GloRefグローバル参照
GloSetグローバル登録
GloKillグローバル削除
DirBlkRdディレクトリブロック読取数
UpntBlkRd上部ポインタブロック読取数
BpntBlkRd下部ポインタブロック読取数
DataBlkRdデータブロック読取数
BdataBlkRdビックデータブロック読取数
MapBlkRdマップブロック読取数
OthBlkRdその他ブロック読取数
DirBlkWtディレクトリブロック書込数
UpntBlkWt上部ポインタブロック書込数
BpntBlkWt下部ポインタブロック書込数
DataBlkWtデータブロック書込数
BdataBlkWtビックデータブロック書込数
MapBlkWtマップブロック書込数
OthBlkWtその他ブロック書込数
DirBlkBufディレクトリ(グローバルバッファ)読取数
UpntBlkBuf上部ポインタ(グローバルバッファ)読取数
BpntBlkBuf下部ポインタ(グローバルバッファ)読取数
DataBlkBufデータ(グローバルバッファ)読取数
BdataBlkBufビッグデータ(グローバルバッファ)読取数
MapBlkBufマップ(グローバルバッファ)読取数
OthBlkBufその他(グローバルバッファ)読取数
JrnEntryジャーナル・エントリ
BlkAlloc割り当てられたブロック
BlockWaitグローバル・バッファへのアクセスを待機
BlockWakeバッファ・リリースでアクティブにされた待機数
RefNoGlo存在しないグローバルを検索
KillNoData削除するものが見つからずにグローバル削除
NetGloRefネットワーク・グローバル参照
NetGloSetネットワーク・グローバル登録
NetGloKillネットワーク・グローバル削除
NetReqSent送信されたネットワーク要求
NCacheHitネットワーク・キャッシュ・ヒット
NCacheMissネットワーク・キャッシュ・ミス
NetLockネットワーク・ロック
RtnLineObjectScript の行
RtnLoadルーチンのロード
RtnFetchルーチンの取得
LockComロック・コマンド
LockSucc成功したロック・コマンド
LockFail失敗したロック・コマンド
LockName名前レベルのロック
TermRead ターミナルの読み取り
TermWriteターミナルの書き込み
TermChRdターミナル読み取り文字数
TermChWrtターミナル書き込み文字数
SeqReadシーケンシャル・リード
SeqWrtシーケンシャル・ライト
MemAllocメモリが割り当てられた回数
MemFreeメモリが解放された回数
IJCMsgRd読み取ったローカル・インタジョブ・コミュニケーション (IJC) メッセージ
IJCMsgWt書き込まれたローカル IJC メッセージ
IJCNetMsg書き込まれたネットワーク IJC メッセージ
BuffSent送信されたネットワーク・バッフ
Time実行時間
TotalTime呼び出し先も含んだ実行時間
Codeコード

おわりに

本記事では、^%SYS.MONLBL を用いた行単位の処理計測について解説しました。

処理のどこに時間がかかっているのかを可視化することで、ボトルネックの特定や無駄な処理の洗い出しが容易になります。

パフォーマンス改善は一度で終わるものではなく、継続的な計測と分析が重要です。

本ツールを活用し、より効率的なアプリケーションの開発・運用にお役立てください。