【IRIS】【計測関連】処理の動きを計測しよう (LineByLine)

本記事では、計測シリーズの一環として、クラス「%Monitor.System.LineByLine」を利用したデータ収集について解説します。

※本記事は以下のような方を対象としています。

ライン（行）ごとの処理速度を知りたい方
どのライン（行）が実行されたかを確認したい方

はじめに
実行の概要
測定開始
測定終了
出力結果の確認
おわりに

はじめに

前回の記事では「%SYS.MONLBL」を使用し、ライン情報やデータのIn/Out等さまざまな情報を取得しました。

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

IRIS の「^%SYS.MONLBL」を用いた行単位の処理計測方法を解説します。対象設定、メトリック選択、CSV出力手順を詳しく紹介し、実行時間やグローバルアクセス可視化によるパフォーマンス分析に役立てられます。

ただし「%SYS.MONLBL」は、測定の開始・終了を手動で行う必要があり、手間と感じる面もあります。

そこで今回紹介するのが、クラス「%Monitor.System.LineByLine」です。

取得できる情報はライン情報に限定されますが、手動設定が不要なため、デバッグの延長として気軽に実行できる点が大きなメリットです。

それでは、実際の使い方を見ていきましょう。

実行の概要

測定対象には、前回使用した関数をそのまま利用します。

d ##class(developer.Sample).lineTest()

Line-By-Lineを使用した測定の流れは下記になります。

【処理の流れ】

「Start」を実行し測定開始
測定対象の関数を実行
「Pause」を実行し測定停止
測定結果をTSV（CSV）ファイルとして出力
「Stop」を実行して測定終了

上記の流れを２つの関数「LineStart」「LineEnd」にラッピングし、最終的な実行コマンドは以下のようになります。

// 測定開始
s routine = $lb("developer.Sample.*")
s metrics = ##class(developer.count.Sample).LineStart(routine)

// 測定対象関数実行
d ##class(developer.Sample).lineTest()

// 測定終了
s dir = [出力先ファイル名].tsv
d ##class(developer.count.Sample).LineEnd(metrics, dir)

※ 手順③～⑤の処理は、関数「LineEnd」でまとめて実行しています。

では、関数「LineStart」「LineEnd」を確認します。

測定開始

まずは、Line-By-Line を開始する関数「LineStart」を確認します。

この関数では、「%Monitor.System.LineByLine」の「Start」を実行しています。

また、本機能は重複実行ができないため、「Start」でエラーが発生した場合には、既存の測定停止を確認する処理も含めています。

【測定開始関数】

ClassMethod LineStart(routine As %List, process As %List = {$lb($j)}) As %String
{
	// 横に長くなるのでマクロを使用
	#define Lbl ##class(%Monitor.System.LineByLine)
	
	// 統計スタート
	s sts = $$$Lbl.Start(routine, "", process)
	i ($$$ISOK(sts)){
		s metrics = $$$Lbl.GetMetrics()
		
		w !,"＜測定対象ルーチン名＞"
		f pos=1:1:$$$Lbl.GetRoutineCount() {
			w !, "　・",$$$Lbl.GetRoutineName(pos)
		}
	}else{
		s metrics = ""
		w !,$system.Status.DisplayError(sts)
		
		s val=1
		i ( (##class(%Prompt).GetYesNo("Line-By-Lineを停止しますか？", .val))&&(val) ){
			s sts = $$$Lbl.Stop()
			i ($$$ISERR(sts)) {
				w !, $system.Status.DisplayError(sts)
			}else{
				w !, "	> 測定を停止しました"
			}
		}
	}
	q metrics
}

ポイント

メトリック（測定項目）を戻り値として返却
戻り値メトリックは、関数「LineEnd」の引数として使用
引数「routine」は、%List型で指定
引数「routine」はワイルドカード「*」が使用可能、末尾に付与する事で対象をまとめて指定

この関数を実行する事で、Line-By-Lineの測定が開始されます。

測定終了

対象関数の処理が完了したら、測定を終了します。

関数「LineEnd」では、以下の処理をまとめて実行しています。

測定の一時停止（Pause）
測定結果の取得
TSV（CSV）ファイルへの出力
測定終了（Stop）

【測定終了関数】

ClassMethod LineEnd(metrics As %String, logPath As %String, dlm As %String = {$c(9)})
{
	// 横に長くなるのでマクロを使用
	#define Lbl ##class(%Monitor.System.LineByLine)


	// 計測中断
	s sts = $$$Lbl.Pause()
	w:($$$ISERR(sts)) !, $system.Status.DisplayError(sts)
	
	
	k ^||temp
	
	
	// 情報取得
	s rs = ##class(%ResultSet).%New("%Monitor.System.LineByLine:Result")
	
	// ルーチンごとに情報表示
	f rtnnum=1:1:$$$Lbl.GetRoutineCount(){
		s rtnname = $$$Lbl.GetRoutineName(rtnnum)
		d rs.Execute(rtnname)

		// ルーチン各行ごとの統計
		s lcnt = 1, hits = 0
		while(rs.Next()) {
			// ヘッダ
			i (lcnt = 1) {
			 	s ^||temp($i(^||temp)) = "***** "_rtnname_" *****"
			 	s ^||temp($i(^||temp)) = "Line"_dlm_$tr(metrics,",",dlm)
			 	
			 	s line = ""
			 	f i=1:1:($l(metrics,",")+3) s line = line_"============"
			 	s ^||temp($i(^||temp)) = line
			 }
			 
			 s col = rs.GetData(1)
			 s ^||temp($i(^||temp)) = lcnt_dlm_$lts(col, dlm)_dlm_$Text(+lcnt^@rtnname)
			 
			 
			 // Coverage 計算用
			 s:($li(col,2)'=0) hits = hits + 1
			 
			 s lcnt = lcnt + 1
		}
		
		// Coverage表示
		i (lcnt > 1) {
			s lineCnt = $zu(84,16,7,rtnnum) // 行数
			s ^||temp($i(^||temp))="Coverage "_+$fn((hits/lineCnt)*100,"",2)_"%"
		}
	}
	s rs=""
	
	
	o logPath:"NWS"
	f pos=1:1:^||temp  u logPath w ^||temp(pos),!
	c logPath
	
	k ^||temp
	
	// 統計ストップ/カウンターリセット
	s sts = $$$Lbl.Stop()
	w:($$$ISERR(sts)) !, $system.Status.DisplayError(sts)
}

補足