パフォーマンス・レポート機能

起動されたアプリケーションの細かい動作をレポートとして出力する機能の説明です。

レポートできる項目として以下のものがあります。

DSMCGI実行の経過時間、CPU時間、メモリー使用量。
B/NOMAD実行の経過時間、CPU時間、メモリー使用量。
プロシージャとエントリーコールのトレース（最大15階層）。
プロシージャとエントリーコールの経過時間、CPU時間、メモリー使用量。
リモートSQLのトレース。
リモートSQL実行の経過時間、CPU時間、メモリー使用量。


パフォーマンス・レポート設定書式

UNIXの場合、「dsmcgi.pr」ファイルに書き込み権限がない場合（DSMにより、「dsmcgi.pr」ファイルが新規に生成される場合など）は、レポートファイルに情報が出力されないことがあります。
「chmod 666 dsmcgi.pr」でレポートファイルの書き込み権限を有効にするようにしてください。

• PerformReport
  パフォーマンス・レポート機能を有効にするかどうかの設定を行います（ON/OFF）。
  この項目を指定しない場合（デフォルト）はOFFです（パフォーマンス・レポート機能を無効にします）。

• prTargetApp
  レポートの対象になるアプリケーションIDまたはアプリケーション名を指定します。複数ある場合は、":"で区切ってください。
  この項目を指定しない場合（デフォルト）は、すべてのアプリケーションがレポート対象になります。
  設定できる最大文字数は255バイトです。

• prCallProcLevel
  レポートする「CALL procedure/entry」レベルを設定します。0〜15階層まで設定可能です。
  この項目を指定しない場合（デフォルト）は0です。

• prRemoteSQL
  リモートデータベース（RDB）へのSQLアクセスをレポート対象にするかどうかを設定します（ON/OFF）。
  この項目を指定しない場合（デフォルト）はOFFです。

• prEachBnomad
  B/NOMADごとにレポートを作成するかどうかを設定します（ON/OFF）。
  ONの場合は、共通のdsmcgi.prの他にdsmcgi.pr0、dsmcgi.pr1、dsmcgi.pr2...へも出力します。
  この項目を指定しない場合（デフォルト）はOFFです。

• MaxPrSizeMB
  dsmcgi.pr、dsmcgi.pr0、dsmcgi.pr1、...それぞれの最大ファイルサイズ（MB）の設定をします。
  この項目を指定しない、または0を指定した場合は、ファイルの最大サイズは無制限です。
  ただし、個々のファイルの最大サイズは、ここで指定したファイルサイズの半分になります。（「dsmcgi.pr」と「dsmcgi.pr_0」両方の最大ファイルサイズの合計がMaxPrSizeMBの指定になります）
  なお、アプリケーションの規模やレポートの出力内容によっては、特にMaxPrSizeMBの設定値が小さい場合に、レポートファイルのサイズが瞬間的にMaxPrSizeMBで設定された半分の値を大幅に上回ることもありますので注意してください。
  

コンソール上でdsmを使用することにより、パフォーマンス・レポートファイルの参照と削除が可能です。

Mon Aug 23 17:09:04.995[438]: => dsmcgi     sid='192.168.0.156_935395745438' app='STG3000_APP'
Mon Aug 23 17:09:05.125[438]:   -> call B/NOMAD[0]
Mon Aug 23 17:09:05.275[438]:     >> B/NOMAD[0][0] (stg3_prf)
Mon Aug 23 17:09:05.285[438]:       -> CALL 'STG3_PRF.STG3_PRF'
Mon Aug 23 17:09:05.315[438]:       <- CALL 'STG3_PRF.STG3_PRF'                  ELP=   30ms CPU=   10ms+    0ms MEM= 7448K
Mon Aug 23 17:09:05.315[438]:     << B/NOMAD[0][0] ELP=   40ms CPU=   10ms+   10ms MEM= 7448K
Mon Aug 23 17:09:05.325[438]:   <- call B/NOMAD[0] ELP=  200ms CPU=   20ms+   10ms MEM= 1720K
Mon Aug 23 17:09:05.355[438]:   -> call B/NOMAD[0]
Mon Aug 23 17:09:05.385[438]:     >> B/NOMAD[0][0] (purge stg3_get_form otw;&STG3_IPNOMADPROC='stg3000';call stg3000.stg3000)
Mon Aug 23 17:09:05.396[438]:       -> CALL 'STG3000.STG3000'
Mon Aug 23 17:09:05.426[438]:         -> CALL 'STG3000.STG3000_START'
Mon Aug 23 17:09:05.426[438]:           -> CALL 'STG3000.DEC_VARIABLES'
Mon Aug 23 17:09:05.426[438]:           <- CALL 'STG3000.DEC_VARIABLES'          ELP=    0ms CPU=    0ms+    0ms MEM= 7556K
Mon Aug 23 17:09:05.426[438]:           -> CALL 'STG3000.DB_ACTIVE'
Mon Aug 23 17:09:05.426[438]:           <- CALL 'STG3000.DB_ACTIVE'              ELP=    0ms CPU=    0ms+    0ms MEM= 7556K
Mon Aug 23 17:09:05.426[438]:         <- CALL 'STG3000.STG3000_START'            ELP=    0ms CPU=    0ms+    0ms MEM= 7556K
Mon Aug 23 17:09:05.436[438]:         -> CALL 'STG3_GET_FORM.STG3_GET_FORM'
Mon Aug 23 17:09:05.456[438]:         <- CALL 'STG3_GET_FORM.STG3_GET_FORM'      ELP=   20ms CPU=   20ms+    0ms MEM= 7688K
Mon Aug 23 17:09:05.456[438]:         -> CALL 'STG3000.ITP_HDL_ACTION'
Mon Aug 23 17:09:05.466[438]:           -> CALL 'STG3000.FACTPBUTACT_A480'
Mon Aug 23 17:09:05.466[438]:             -> CALL 'STG3010.STG3010'
Mon Aug 23 17:09:05.556[438]:               -> CALL 'STG3010.STG3010_START'
Mon Aug 23 17:09:05.556[438]:                 -> CALL 'STG3010.DEC_VARIABLES'
Mon Aug 23 17:09:05.566[438]:                 <- CALL 'STG3010.DEC_VARIABLES'    ELP=   10ms CPU=    0ms+    0ms MEM= 7924K
Mon Aug 23 17:09:05.566[438]:                 -> CALL 'STG3010.DB_ACTIVE'
Mon Aug 23 17:09:05.566[438]:                 <- CALL 'STG3010.DB_ACTIVE'        ELP=    0ms CPU=    0ms+    0ms MEM= 7924K
Mon Aug 23 17:09:05.566[438]:               <- CALL 'STG3010.STG3010_START'      ELP=   10ms CPU=    0ms+   11ms MEM= 7924K
Mon Aug 23 17:09:05.566[438]:               -> CALL 'STG3010.ITP_HDL_ACTION'
Mon Aug 23 17:09:05.566[438]:                 -> CALL 'STG3010.INITIAL_SET_SUB'
Mon Aug 23 17:09:05.566[438]:                 <- CALL 'STG3010.INITIAL_SET_SUB'  ELP=    0ms CPU=    0ms+    0ms MEM= 7924K
Mon Aug 23 17:09:05.576[438]:               <- CALL 'STG3010.ITP_HDL_ACTION'     ELP=   10ms CPU=   10ms+    0ms MEM= 7924K
Mon Aug 23 17:09:05.576[438]:               -> CALL 'STG3010.ITP_UPD_HTMLOUT'
Mon Aug 23 17:09:05.726[438]:               <- CALL 'STG3010.ITP_UPD_HTMLOUT'    ELP=  150ms CPU=   40ms+   30ms MEM= 7932K
Mon Aug 23 17:09:05.726[438]:             <- CALL 'STG3010.STG3010'              ELP=  260ms CPU=   50ms+   41ms MEM= 7932K
Mon Aug 23 17:09:05.726[438]:           <- CALL 'STG3000.FACTPBUTACT_A480'       ELP=  260ms CPU=   50ms+   41ms MEM= 7932K
Mon Aug 23 17:09:05.726[438]:         <- CALL 'STG3000.ITP_HDL_ACTION'           ELP=  270ms CPU=   60ms+   41ms MEM= 7932K
Mon Aug 23 17:09:05.726[438]:       <- CALL 'STG3000.STG3000'                    ELP=  330ms CPU=  100ms+   41ms MEM= 7932K
Mon Aug 23 17:09:05.736[438]:     << B/NOMAD[0][0] ELP=  351ms CPU=  120ms+   51ms MEM= 7932K
Mon Aug 23 17:09:05.746[438]:   <- call B/NOMAD[0] ELP=  391ms CPU=   10ms+   20ms MEM= 1732K
Mon Aug 23 17:09:05.776[438]: <= dsmcgi            ELP=  781ms CPU=   70ms+  190ms MEM= 1744K
	

パラメータの意味は以下のようになります。

ELP：経過時間（elapse）。単位はms。
CPU：CPU時間 = ユーザーが使用したCPU時間 + システムが使用したCPU時間。単位はms。
MEM：その時点のプロセス・メモリーサイズ(KB)。

すべて時間関連のパラメータは入り口（=>、->、>>）でリセットされ、出口（<=、<-、<<）で計測した値を出力します。