【PL/SQL】DBMS_PROFILERで行レベル分析する完全ガイド｜分析SQL7種・40倍速ケーススタディ・CI連携・HPROF比較

-- ① DBA権限でパッケージをインストール（一度だけ）
SQL> CONNECT / AS SYSDBA
SQL> @?/rdbms/admin/profload.sql

-- ② 結果格納テーブルを作成（プロファイリングを行うスキーマで実行）
SQL> CONNECT app_user/password
SQL> @?/rdbms/admin/proftab.sql

-- 作成される3つの表
-- - PLSQL_PROFILER_RUNS  : 計測実行（RUN）のメタ情報
-- - PLSQL_PROFILER_UNITS : RUN内で計測されたコンパイル単位（パッケージ等）
-- - PLSQL_PROFILER_DATA  : 行ごとの実行回数・時間（中心テーブル）

-- ③ 各テーブルの主要カラム確認
DESC PLSQL_PROFILER_RUNS;
-- RUNID NUMBER (PK)
-- RELATED_RUN NUMBER
-- RUN_OWNER VARCHAR2(32)
-- RUN_DATE DATE
-- RUN_COMMENT VARCHAR2(2047)
-- RUN_TOTAL_TIME NUMBER

DESC PLSQL_PROFILER_UNITS;
-- RUNID NUMBER (FK)
-- UNIT_NUMBER NUMBER
-- UNIT_TYPE VARCHAR2(32)
-- UNIT_OWNER VARCHAR2(32)
-- UNIT_NAME VARCHAR2(32)
-- UNIT_TIMESTAMP DATE
-- TOTAL_TIME NUMBER

DESC PLSQL_PROFILER_DATA;
-- RUNID NUMBER (FK)
-- UNIT_NUMBER NUMBER
-- LINE# NUMBER       -- ソースコード行番号
-- TOTAL_OCCUR NUMBER -- 実行回数
-- TOTAL_TIME NUMBER  -- 累計時間（ナノ秒）
-- MIN_TIME NUMBER    -- 1回あたり最小時間
-- MAX_TIME NUMBER    -- 1回あたり最大時間

-- ① 計測開始（RUNIDが返る）
DECLARE
  v_runid NUMBER;
BEGIN
  DBMS_PROFILER.START_PROFILER(
    run_comment => '20260425_BEFORE_FIX',
    runid       => v_runid
  );
  DBMS_OUTPUT.PUT_LINE('RUNID = ' || v_runid);
END;
/

-- ② 計測対象を実行（普通に呼ぶだけ）
BEGIN
  pkg_order_service.create_order(p_customer_id => 100, p_amount => 5000);
END;
/

-- ③ 計測停止
BEGIN
  DBMS_PROFILER.STOP_PROFILER;
END;
/

-- ④ どのRUNが今回のものか確認
SELECT runid, run_date, run_comment, run_total_time/1e9 AS sec
  FROM plsql_profiler_runs
 ORDER BY runid DESC
 FETCH FIRST 5 ROWS ONLY;

-- 最も時間を食っている行TOP10を特定する基本クエリ
-- これだけで70%のボトルネック特定が完了する
SELECT
  u.unit_name,
  d.line# AS line_num,
  d.total_occur AS occur,
  d.total_time/1e6 AS total_ms,
  ROUND(d.total_time/d.total_occur/1e3, 2) AS avg_us,
  ROUND(d.max_time/1e3, 2) AS max_us
FROM plsql_profiler_data d
JOIN plsql_profiler_units u
  ON d.runid = u.runid AND d.unit_number = u.unit_number
WHERE d.runid = &runid
  AND d.total_time > 0
ORDER BY d.total_time DESC
FETCH FIRST 10 ROWS ONLY;

-- 行番号とソースコードを並べて、どこが遅いか一目で分かる
WITH heavy AS (
  SELECT u.unit_owner, u.unit_name, u.unit_type, d.line#,
         d.total_time, d.total_occur,
         RANK() OVER (ORDER BY d.total_time DESC) rk
  FROM plsql_profiler_data d
  JOIN plsql_profiler_units u
    ON d.runid = u.runid AND d.unit_number = u.unit_number
  WHERE d.runid = &runid
    AND d.total_time > 0
)
SELECT h.unit_name, h.line#,
       h.total_time/1e6 AS total_ms,
       h.total_occur AS occur,
       s.text AS source_line
  FROM heavy h
  JOIN all_source s
    ON  s.owner = h.unit_owner
    AND s.name  = h.unit_name
    AND s.type  = h.unit_type
    AND s.line  = h.line#
 WHERE h.rk <= 20
 ORDER BY h.rk;

-- 呼び出し回数が多い行は「ループ内のホットスポット」の可能性大
SELECT u.unit_name, d.line#,
       d.total_occur AS occur,
       d.total_time/1e6 AS total_ms,
       ROUND(d.total_time/d.total_occur/1e3, 2) AS avg_us
  FROM plsql_profiler_data d
  JOIN plsql_profiler_units u
    ON d.runid = u.runid AND d.unit_number = u.unit_number
 WHERE d.runid = &runid
   AND d.total_occur > 0
 ORDER BY d.total_occur DESC
 FETCH FIRST 10 ROWS ONLY;
-- → 数十万回・数百万回呼ばれている行は集合演算で書き換えるべき候補

-- max_time が突出して大きい行は「たまに極端に遅くなる」処理
SELECT u.unit_name, d.line#,
       d.total_occur AS occur,
       d.total_time/1e6 AS total_ms,
       ROUND(d.max_time/1e3, 2) AS max_us,
       ROUND(d.min_time/1e3, 2) AS min_us
  FROM plsql_profiler_data d
  JOIN plsql_profiler_units u
    ON d.runid = u.runid AND d.unit_number = u.unit_number
 WHERE d.runid = &runid
   AND d.max_time > 1000000   -- 1ms以上のもの
 ORDER BY d.max_time DESC
 FETCH FIRST 10 ROWS ONLY;
-- → ロック待ち・統計情報の偏りなどイレギュラー処理を疑う

-- どのパッケージが全体時間の何%を占めているかを把握
SELECT u.unit_owner, u.unit_name, u.unit_type,
       SUM(d.total_time)/1e6 AS total_ms,
       ROUND(SUM(d.total_time) * 100.0 /
             (SELECT SUM(total_time) FROM plsql_profiler_data WHERE runid = &runid),
             2) AS pct_total
  FROM plsql_profiler_data d
  JOIN plsql_profiler_units u
    ON d.runid = u.runid AND d.unit_number = u.unit_number
 WHERE d.runid = &runid
 GROUP BY u.unit_owner, u.unit_name, u.unit_type
 ORDER BY total_ms DESC;

-- 修正前後で行ごとの時間がどう変化したか確認
SELECT u.unit_name, d_before.line#,
       d_before.total_time/1e6 AS before_ms,
       d_after.total_time/1e6  AS after_ms,
       ROUND((d_before.total_time - d_after.total_time)/1e6, 2) AS saved_ms,
       ROUND((d_before.total_time - d_after.total_time)
             / NULLIF(d_before.total_time, 0) * 100, 1) AS pct_saved
  FROM plsql_profiler_data d_before
  JOIN plsql_profiler_data d_after
    ON d_before.unit_number = d_after.unit_number
   AND d_before.line# = d_after.line#
  JOIN plsql_profiler_units u
    ON u.runid = d_before.runid
   AND u.unit_number = d_before.unit_number
 WHERE d_before.runid = &before_runid
   AND d_after.runid  = &after_runid
   AND d_before.total_time > 1e6   -- 1ms以上のみ表示
 ORDER BY saved_ms DESC;

-- 毎回同じクエリを書かないよう専用ビューを定義
CREATE OR REPLACE VIEW v_profiler_summary AS
SELECT r.runid,
       r.run_comment,
       r.run_date,
       u.unit_owner,
       u.unit_name,
       d.line# AS line_num,
       d.total_occur AS occur,
       d.total_time/1e6 AS total_ms,
       d.max_time/1e3 AS max_us,
       d.min_time/1e3 AS min_us,
       ROUND(d.total_time/NULLIF(d.total_occur,0)/1e3, 2) AS avg_us,
       s.text AS source_line
  FROM plsql_profiler_runs r
  JOIN plsql_profiler_units u  ON u.runid = r.runid
  JOIN plsql_profiler_data  d  ON d.runid = u.runid AND d.unit_number = u.unit_number
  LEFT JOIN all_source s
    ON s.owner = u.unit_owner AND s.name = u.unit_name
   AND s.type = u.unit_type   AND s.line = d.line#;

-- 利用例：直近のRUNでTOP10を一発取得
SELECT *
  FROM v_profiler_summary
 WHERE runid = (SELECT MAX(runid) FROM plsql_profiler_runs)
 ORDER BY total_ms DESC
 FETCH FIRST 10 ROWS ONLY;

UNIT_NAME       LINE_NUM  OCCUR     TOTAL_MS   AVG_US
PKG_ORDER         15      100,000   39,520     395
PKG_ORDER         28      100,000    2,150      21
PKG_ORDER         12      100,000    1,030      10
PKG_ORDER         42        1,000      850     850
PKG_ORDER         31      100,000      720       7
...

-- 15行目のソース：
SELECT name INTO v_name FROM countries WHERE code = rec.country_code;
-- → 10万回も同じ表を引いている。連想配列キャッシュで置換すべき

-- 連想配列で事前ロード
DECLARE
  TYPE t_map IS TABLE OF VARCHAR2(100) INDEX BY VARCHAR2(2);
  v_country t_map;
  v_name    VARCHAR2(100);
BEGIN
  -- 一度だけマスタを取得（250件）
  FOR rec IN (SELECT code, name FROM countries) LOOP
    v_country(rec.code) := rec.name;
  END LOOP;

  -- メインループでメモリlookup（SQLゼロ）
  FOR rec IN (SELECT customer_id, country_code, ... FROM customers) LOOP
    v_name := v_country(rec.country_code);   -- ← O(1)
    -- 業務処理
  END LOOP;
END;
/

-- リリース前の自動プロファイリング
-- 前提：plsql_profiler_runs に過去のRUNが残っている
SET SERVEROUTPUT ON
DECLARE
  v_runid     NUMBER;
  v_curr_ms   NUMBER;
  v_prev_ms   NUMBER;
  v_threshold NUMBER := 1.20;   -- 前回比20%増を許容
BEGIN
  -- 計測開始
  DBMS_PROFILER.START_PROFILER(
    run_comment => 'CI_' || TO_CHAR(SYSDATE,'YYYYMMDD_HH24MI'),
    runid       => v_runid);

  -- 標準テストシナリオを実行
  pkg_perf_test.run_smoke_scenario;

  DBMS_PROFILER.STOP_PROFILER;

  -- 今回のRUNの合計時間
  SELECT run_total_time/1e6 INTO v_curr_ms
    FROM plsql_profiler_runs WHERE runid = v_runid;

  -- 前回のCI RUNを取得
  SELECT MIN(run_total_time)/1e6 INTO v_prev_ms
    FROM plsql_profiler_runs
   WHERE run_comment LIKE 'CI_%'
     AND runid < v_runid
     AND run_date > SYSDATE - 30;

  IF v_prev_ms IS NOT NULL AND v_curr_ms > v_prev_ms * v_threshold THEN
    RAISE_APPLICATION_ERROR(-20999,
      '性能リグレッション検出: ' || v_curr_ms || 'ms (前回: ' || v_prev_ms || 'ms)');
  END IF;

  DBMS_OUTPUT.PUT_LINE('OK: ' || v_curr_ms || 'ms');
END;
/