【IRIS】【計測関連】リアルタイムで状況を確認しよう (^PROFILE)

本記事は、計測シリーズとして「^PROFILE」を使用し、グローバル活動の計測方法について解説します。

※この記事は下記の方向けになります。
  • リアルタイムで状況を確認したい方
  • システムの問題点を特定したい方

はじめに

^PROFILE は、ルーチンやクラスのパフォーマンスを分析するためのツールです。
処理のボトルネックを特定し、改善ポイントを数値ベースで把握できます。

^PROFILE は、以下の 2 つのフェーズで構成されています。

フェーズ構成
  1. 第1フェーズ:負荷の高いルーチン・クラスを特定する
  2. 第2フェーズ:対象の詳細(関数・行レベル)を分析する

これらをリアルタイムでモニタリング可能です。

では、確認してみましょう。

^PROFILE開始

^PROFILE を実行するには、ネームスペースを「%SYS」に変更してから起動します。

zn "%SYS"
d ^PROFILE

実行すると、以下の警告メッセージが表示されます。
(※警告文はそのまま掲載)

WARNING: 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 the initial collection,
and it could significantly affect a busy system.
 
The second phase of collecting line level detail activity
has high overhead and should ONLY BE RUN ON A TEST SYSTEM!
 
Are you ready to start the collection?  Yes =>

警告: このルーチンは、システム全体のルーチンアクティビティに関するデータ収集を開始し、結果を表示します。
最初の収集には多少のオーバーヘッドが発生する可能性があり、
高負荷のシステムでは大きな影響を与える可能性があります。

行レベルの詳細アクティビティを収集する第2フェーズは、
オーバーヘッドが大きいため、テストシステムでのみ実行してください。

収集を開始する準備はできましたか? はい =>

→ 問題なければ Enter を押下して開始します。

「Enter」押下後「Waiting for initial data collection …」が表示され、フェーズ1:負荷の高いルーチン・クラスを確認する事が出来ます。

第1フェーズ:全体傾向の把握

第1フェーズは、インスタンス全体を俯瞰し、ボトルネックの「あたり」を付けるための初期調査フェーズです。

ここでは、

「どのルーチン・クラスに問題があるか?」

を数値で把握します。

この段階で対象選定を誤ると、後続の詳細分析の効果が薄れるため、非常に重要なステップです。

下記サンプル画像は、複数のターミナルで処理を実行している際に実行したサンプル画面です。

■サンプル画面

DB「SAMPLE」にある、class「developer.Sample.CLS」が一番活性化している事が分ります。

■指標

項目名説明
RtnLine実行された行数
Time処理時間
CPUCPU使用時間
RtnLoadルーチンのロード回数
GloRefグローバル参照数
GloSetグローバル更新数

操作方法(第1フェーズ)

1ページに11件しか表示されません。
※ ターミナルサイズを変更しても11件は変わらず

確認したいルーチン・クラスが表示されていない場合、ページ操作が必要です。

画面下部に表示される入力箇所から操作を行います。

Select routine(s) or ‘?’ for more options N =>

指示コマンド説明
数値
数値-数値
対象ルーチンを選択(入力例)1, 2-5, 10)
 ※ 選択後、名称の左に「*」が表示
N / B次ページ / 前ページ
Oソート変更
Q選択なし:^PROFILEの終了
選択あり:フェーズ2へ進む
Rリスト更新
X選択の全解除(他ページも含む)を行い、リストを更新する。

指示コマンド:数値, 数値-数値

詳細を確認するクラスとして、下記5クラスを対象とします。

  • developer.Sample.CLS
  • developer.jor.Sample.CLS
  • developer.json.Sample.CLS
  • developer.csv.Sample.CLS (別ページ)
  • developer.text.Sample.CLS (別ページ)

↓ 選択したNo.2, 3, 9 には「*」が付与されます。

「N or n:ページを進める」、「B or b:ページを戻す」を使用し、目的のルーチン・クラスを選択します。

指示コマンド:O or o (ソート方法を変える)

初期表示時は「1) Lines of code executed」順で表示されていましたが、下記の通り並び順の方法を変更できます。

ソート方法を選択したら、次は百分率かカウンター値のどちらで比較するか選択します。

最後は、自動更新間隔を選択します。
0:自動更新しない、1~:指定間隔で自動更新を行う

全ての選択が完了すると、選択したソート方法が反映された形でリスト画面に戻ります。

指示コマンド:Q or q (フェーズ2へ進む)

予定していた5つのクラスを選択したら、「Q」を入力し、第2フェーズへ進みます。

「Q」入力後、ターミナルには下記表示が行われます。
問題が無ければEnterを押下してください。

詳細プロファイリング用に5つのルーチンが選択されています。ルーチンレベルの収集を終了し、詳細プロファイラー収集を開始できます。

警告!!

これにより、システム上の各プロセスがこれらのルーチンのサブルーチンレベルおよび行レベルのアクティビティを収集します。収集のこの部分はパフォーマンスに大きな影響を与える可能性があるため、テストインスタンスまたは開発インスタンスでのみ実行してください。

詳細収集を開始する準備はできましたか? はい =>

第2フェーズ:詳細分析

第2フェーズでは、第1フェーズで特定した対象を深掘りし、原因箇所を特定します。

分析の流れ
  1. ルーチン・クラス単位での確認
  2. ラベル・関数単位での確認
  3. 行単位の確認

これにより、「どの処理が遅いか」だけでなく、

どの行が原因か

まで特定可能です。

ルーチン・クラス単位での確認

最初のステップでは、第1フェーズで抽出したクラス・ルーチンを指定し、その内部で「どの関数(メソッド)がどれだけの負荷を持っているか」を確認します。

■サンプル画面

指示コマンド説明
数値選択したルーチン・クラスの「関数レベル」での詳細な情報を取得します。
N / B次ページ / 前ページ
Oソート変更
Q^PROFILEの終了
Rリスト更新

調査対象のルーチン・クラスの番号を選択しましょう。

今回は、クラス「developer.Sample.CLS」を深掘りしたいので、「1」を入力します。

指示コマンド:O or o (ソート方法を変える)

ソート方法を変更します。

ソート方法を選択したら、次は百分率かカウンター値のどちらで比較するか選択します。

全ての選択が完了すると、選択したソート方法が反映された形でリスト画面に戻ります。

指示コマンド:Q or q (^PROFILEを終了する)

^PROFILEを終了するには、「Q」を入力します。

「Q」を入力すると下記旨の確認が表示されます。

プロフィール収集を停止しますか(収集されたデータは削除されます)?
いいえ =>

「Y」を入力すると、収集したデータを削除して^PROFILEを終了します。

「N」を入力すると、再度「d ^PROFILE」すると、第2フェーズから開始する事ができます。

ラベル・関数単位での確認

ルーチン・クラス単位で特定した「重たいラベル・関数」を特定し、さらにラインレベルへと掘り下げていきます。

先ほど選択した「developer.Sample.CLS」をサンプル画像としています。
ラベル・関数名と引数が表示されています。

詳細確認を行う関数の番号を入力して下さい。

また、「Tag.1 developer.Sample.1」を選択すると、INTルーチンの最初の行から表示されます。

■サンプル画像

指示コマンド説明
数値選択したルーチン・クラスの「関数レベル」での詳細な情報を取得します。
N / B次ページ / 前ページ
Q第2フェーズ – クラス選択に戻る
Rリスト更新

今回は、ターミナルで実行している関数を確認したいので、ページを進めて「54」を入力します。

他の指示コマンドに関しては、他と変わらない為割愛します。

ラインレベル分析のポイント

最後のステップでは、関数内の個々の行に対して、さらに詳細な実行状況を確認します。

行単位の分析では、以下の観点が重要です。

  • 無駄なループがないか
  • インデックスが適切に利用されているか
  • グローバルアクセスが過剰でないか
  • キャッシュ可能な処理がないか

■サンプル画像

指示コマンド説明
数値該当行を表示します。
N / B次ページ / 前ページ
Cコードの表示切替(ソース・コード / 中間 (INT/MVI) コード)
Oメトリックの変更とページの並べ替え
M1行の表示文字数と列数の変更
Q第2フェーズ – ルーチン・クラス選択に戻る
Rリスト更新

指示コマンド:M or m (表示領域を広げる)

デフォルトの表示は見づらいため、mコマンドで表示幅を拡張します。

■サンプル画像
折り返しが発生していて、とても見辛い。

[編集] > [ウィンドウサイズ] より、ターミナルのサイズを変更します。

ターミナルのサイズを変更しても、コードが折り返しています。

1行の表示を下記に変更してみます。

  • 行幅:200
  • 列数:45

コードの可読性が大幅に向上します。

指示コマンド:O or o (メトリックの変更)

表示するメトリックを変更します。
変更できるメトリックは下記4種です。

おわりに

^PROFILE は単なる監視ツールではなく、

「どこを直せば、どれだけ速くなるか」を示す診断ツール

です。

経験則に頼りがちなパフォーマンスチューニングに対し、

  • なぜ遅いのか
  • どの行が問題なのか
  • 本当にそこを直すべきなのか

を数値で判断できる点が大きな強みです。

「何となく重い」状態から、

「このクラスのこの行が原因」

と特定できる状態へ。

ぜひ、^PROFILE を活用してみてください。