【PL/SQL】DBMS_PROFILERでコード実行時間を計測する方法

【PL/SQL】DBMS_PROFILERでコード実行時間を計測する方法 PL/SQL

DBMS_PROFILERはPL/SQLコードの行単位で実行回数や経過時間を計測し、どこが遅いのかを数値で可視化できる標準パッケージです。体感やログだけでは見えないボトルネックを特定し、最小の修正で最大の効果を狙うための強力な手段になります。ここではセットアップから計測の開始・停止、結果の読み方、実運用の勘所までを一気通貫で解説します。

前提準備とセットアップ

DBMS_PROFILERを使うには専用の計測結果テーブル群を用意します。多くの環境では管理者が一度だけプロファイラ用スキーマに対してスクリプトを流します。Oracleサーバ上の$ORACLE_HOME/rdbms/admin/profload.sqlを実行するとPLSQL_PROFILER_RUNSPLSQL_PROFILER_UNITSPLSQL_PROFILER_DATAなどの表およびパッケージ公開権限が準備されます。アプリの実行スキーマから参照する場合はこれら表へのINSERT/SELECT権限とDBMS_PROFILERのEXECUTE権限を付与します。計測はセッション単位で行われるため、接続プールやツールごとに同じ前提を整えておくと安定します。

最小手順:開始・停止と結果保存

計測の基本は「開始 → 対象処理実行 → 停止 → 結果参照」という流れです。開始時にランIDが発番され、停止時点までの行ごとの回数・時間が集計されます。

-- 計測を開始(コメントは任意、ランIDが返る)
DECLARE
  v_runid NUMBER;
BEGIN
  DBMS_PROFILER.START_PROFILER(run_comment => '月次バッチ step1', runid => v_runid);
  DBMS_OUTPUT.PUT_LINE('RUNID='||v_runid);
END;
/

-- <ここで対象プロシージャやSQLを実行>

-- 計測を停止(バッファのフラッシュも行う)
BEGIN
  DBMS_PROFILER.STOP_PROFILER;
END;
/

バッチの途中で小刻みに結果を吐きたい場合はDBMS_PROFILER.FLUSH_DATAを呼び出します。長時間ジョブで途中結果を観察したいときに有効です。

対象コードのサンプル

計測対象は通常のPL/SQLです。無変更で計測できますが、境界を明確にしたいときはコメントやログを入れておくと後の分析がしやすくなります。

CREATE OR REPLACE PROCEDURE demo_job(p_deptno NUMBER) IS
  v_total NUMBER := 0;
BEGIN
  FOR r IN (SELECT empno, sal FROM emp WHERE deptno = p_deptno) LOOP
    v_total := v_total + r.sal;
  END LOOP;

  INSERT INTO emp_log(deptno, total_sal, logged_at)
  VALUES (p_deptno, v_total, SYSTIMESTAMP);

  COMMIT;
END;
/

結果の見方:ホットスポットの特定

停止後、結果はプロファイラ表に保存されています。まずはランのサマリを確認し、次にユニット(パッケージ・プロシージャ)別、さらに行番号別に掘り下げます。

-- ランの一覧
SELECT runid, run_comment, run_timestamp
  FROM plsql_profiler_runs
 ORDER BY runid DESC;

-- ユニット別の合計時間(ミリ秒換算)
SELECT u.runid, u.unit_owner, u.unit_name,
       ROUND(SUM(d.total_time)/10000,2) AS total_ms
  FROM plsql_profiler_units u
  JOIN plsql_profiler_data  d ON d.runid=u.runid AND d.unit_number=u.unit_number
 WHERE u.runid = :runid
 GROUP BY u.runid, u.unit_owner, u.unit_name
 ORDER BY total_ms DESC;

-- 行番号別のホットスポット
SELECT d.line#, d.total_occur,
       ROUND(d.total_time/10000,2) AS total_ms,
       ROUND(d.min_time/10000,2)   AS min_ms,
       ROUND(d.max_time/10000,2)   AS max_ms
  FROM plsql_profiler_units u
  JOIN plsql_profiler_data  d
    ON d.runid=u.runid AND d.unit_number=u.unit_number
 WHERE u.runid = :runid
   AND u.unit_name = 'DEMO_JOB'
 ORDER BY total_ms DESC;

total_timeは100分のマイクロ秒単位で記録されます。表示時は10,000で割るとミリ秒に変換できます。合計時間の大きい行がボトルネック候補で、出現回数に対する平均時間や最大時間も合わせて観察すると勘所が掴めます。

よくある読み取りの落とし穴と対処

プロファイラ時間はPL/SQL側の消費であり、待機事象やI/Oの詳細は含みません。SQLの実行計画や待機はSQLトレース(10046)やASH/AWRと併用して読み解きます。トリガーや関数がSQL中から頻繁に呼ばれると行単位の時間が散って見えるため、集合志向に寄せる設計へ書き換える判断が有効です。COMMITやネットワーク越しのRPCが多い場合は、PL/SQL側では軽く見えても全体遅延の主因になり得るため、ランタイム統計と合わせて判断します。

ランの分割・コメントとベースライン運用

同じジョブでも入力データ量や条件で特性が変わります。開始時のrun_commentにデータ量や条件、ビルド番号を必ず記録しておくと比較が容易です。修正前後で同条件のランを取り、合計時間とホット行の時間差を見比べると回帰の検出に役立ちます。

長時間バッチとフラッシュ戦略

メモリ保持時間が長い処理では定期的にDBMS_PROFILER.FLUSH_DATAを呼び出し、途中経過をディスクへ吐き出します。障害時にも直前までのデータが残るため、原因究明が速くなります。フラッシュの頻度は数分〜十数分を目安に、I/O負荷と解像度のバランスで決めます。

クリーニングと保守

テーブルサイズは計測を重ねるほど増えます。保持期間と削除ポリシーを決め、古いランを定期削除します。依存するユニットが再作成されても旧ランは参考になるため、最低限の履歴は残すのが実務的です。

DELETE FROM plsql_profiler_data  WHERE runid IN (SELECT runid FROM plsql_profiler_runs WHERE run_timestamp < SYSDATE - 30);
DELETE FROM plsql_profiler_units WHERE runid IN (SELECT runid FROM plsql_profiler_runs WHERE run_timestamp < SYSDATE - 30);
DELETE FROM plsql_profiler_runs  WHERE run_timestamp < SYSDATE - 30;
COMMIT;

DBMS_HPROFとの使い分け

スタックの階層関係や壁時計時間を重視する場合は階層型プロファイラ(DBMS_HPROF)も選択肢になります。行粒度でのホットスポット特定や差分比較を素早く回すならDBMS_PROFILERが軽量で便利です。目的に応じて併用すると分析の視界が広がります。

まとめ

DBMS_PROFILERは「どのユニットのどの行がどれだけ時間を使っているか」を客観的に示す計測器です。セットアップを済ませたら、開始・停止・参照の最小サイクルでホットスポットを特定し、SQLの集合化やBULK処理、不要処理の削減といった定石で改善します。ランのコメント管理と定期的なクリーニングを運用に組み込み、ベースライン比較を継続すれば、安定して速いPL/SQLを維持できます。