コマンドでプロシジャの処理時間を計測しよう！

2024年3月23日テクニカルメモ

概要

WebFOCUSのプロシジャの各行ごとの処理時間を計測することができます。

各行の処理に掛かっている処理時間を明確化することでどこの処理にボトルネックがあるのかを把握することができます。

デバックコマンドをプロシジャの先頭に指定し、実行結果のHTMLソースを参照することで処理時間の確認ができます。

コマンド

以下のコマンドをプロシジャの先頭に追加します。

-SET &ECHO = ALL;
SET NWTIMESTAMP = ON
LET PCHOLD=HOLD
-RUN

コマンド解説

プロシジャのデバックを有効化

-SET &ECHO = ALL;

ブラウザのHTMLソースにプロシジャの処理内容が書き出されます。

プロシジャの処理時間の表示を有効化

SET NWTIMESTAMP = ON

プロシジャの処理内容に各処理の処理時間を表示します。

画面出力コマンドの無効化

LET PCHOLD=HOLD

画面出力せずにECHOログを画面上に出力するために、レポートの画面出力を無効にします。

サンプル

このサンプルでは、仮の処理時間を設けるために、SLEEP関数を利用して1行辺りに0.1秒の待ち時間を入れています。20行の処理を行っているので2秒程度の処理時間としているイメージです。

-SET &ECHO = ALL;
SET NWTIMESTAMP=ON
LET PCHOLD=HOLD
-RUN
-TYPE 始まり
SLEEP 1
-RUN
TABLE FILE GGSALES
 PRINT SEQ
       COMPUTE SLEEP/D4 = SLEEP(0.1,'D4'); NOPRINT
 WHERE SEQ LE 20
 ON TABLE PCHOLD FORMAT HTML
END
-RUN
-TYPE 終わり

結果イメージ

レポート作成処理（TABLEリクエスト）は、「16:05:17 ～ 16:05:20」となっているので約2～3秒程度掛かっていることが分かります。

プロシジャのレコード毎の処理時間を計測するサンプル

COMPUTE処理として、DT_CURRENT_DATETIME(MICROSECOND)を行うと、その処理タイミングの時間を測定することができます。

TABLE FILE GGSALES
 PRINT SEQ
       COMPUTE NOWTIME/HYYMDs = DT_CURRENT_DATETIME(MICROSECOND);
 WHERE SEQ LE 100
END

結果イメージ

1行単位の処理時間を表示しています。

テクニカルメモ