【Oracle】SQL Trace・tkprof 完全ガイド｜10046トレースの取得から tkprof によるボトルネック分析まで解説

-- 方法①: 基本的な SQL Trace（統計のみ）
ALTER SESSION SET SQL_TRACE = TRUE;

-- ここで対象の SQL を実行する
SELECT COUNT(*) FROM employees WHERE department_id = 60;
-- ...アプリケーションを操作する...

-- トレースを終了する
ALTER SESSION SET SQL_TRACE = FALSE;

-- 方法②: 10046イベント（レベル指定あり）
-- level 1: SQL Trace 相当（統計のみ）
-- level 4: バインド変数の値も記録する
-- level 8: 待機イベントも記録する
-- level 12: バインド変数 + 待機イベントの両方（最も詳細）
ALTER SESSION SET EVENTS '10046 trace name context forever, level 12';

-- トレースを終了する
ALTER SESSION SET EVENTS '10046 trace name context off';

-- トレースファイルに識別子を付ける（後で検索しやすくなる）
ALTER SESSION SET TRACEFILE_IDENTIFIER = 'my_diagnosis';
-- → トレースファイル名に 'my_diagnosis' が含まれるようになる

-- Oracle 11g 以降（Automatic Diagnostic Repository を使う環境）
-- V$DIAG_INFO でトレースファイルの場所を確認する
SELECT name, value FROM V$DIAG_INFO
WHERE  name IN ('Diag Trace', 'Default Trace File');
-- Diag Trace: トレースファイルが格納されるディレクトリ
-- Default Trace File: 現在のセッションのトレースファイルのフルパス

-- 現在のセッションの SID・プロセス番号からファイル名を特定する
SELECT
    s.sid,
    s.serial#,
    p.spid       AS os_pid,     -- OS プロセス ID（ファイル名に使われる）
    s.username,
    s.tracefile                 -- 11g 以降は V$SESSION に tracefile 列がある
FROM   V$SESSION s
JOIN   V$PROCESS p ON s.paddr = p.addr
WHERE  s.audsid = SYS_CONTEXT('USERENV', 'SESSIONID');

-- Oracle 10g 以前（USER_DUMP_DEST を使う）
SHOW PARAMETER user_dump_dest;
-- トレースファイル名のパターン: <SID>_ora_<SPID>.trc
-- 例: orcl_ora_12345.trc

-- 別セッション（SID + SERIAL#）のトレースを有効にする（DBA権限が必要）
-- 対象セッションの SID と SERIAL# を確認する
SELECT sid, serial#, username, status FROM V$SESSION WHERE username = 'APP_USER';

EXEC DBMS_MONITOR.SESSION_TRACE_ENABLE(
    session_id    => 42,         -- SID
    serial_num    => 1234,       -- SERIAL#
    waits         => TRUE,       -- 待機イベントを記録する
    binds         => TRUE        -- バインド変数の値を記録する
);

-- 対象セッションのトレースを終了する
EXEC DBMS_MONITOR.SESSION_TRACE_DISABLE(
    session_id => 42,
    serial_num => 1234
);

-- サービス名 + モジュール名 + アクション名の組み合わせでトレースを有効にする
-- アプリケーションが DBMS_APPLICATION_INFO でモジュール名を設定している場合に使う
EXEC DBMS_MONITOR.SERV_MOD_ACT_TRACE_ENABLE(
    service_name  => 'ORCL',
    module_name   => 'OrderProcess',  -- DBMS_APPLICATION_INFO.SET_MODULE で設定した名前
    action_name   => DBMS_MONITOR.ALL_ACTIONS,  -- NULL ですべてのアクション
    waits         => TRUE,
    binds         => FALSE
);

EXEC DBMS_MONITOR.SERV_MOD_ACT_TRACE_DISABLE(
    service_name  => 'ORCL',
    module_name   => 'OrderProcess',
    action_name   => DBMS_MONITOR.ALL_ACTIONS
);

-- 現在のセッションから DBMS_SESSION でトレースを有効にする
EXEC DBMS_SESSION.SET_SQL_TRACE(sql_trace => TRUE);
EXEC DBMS_SESSION.SET_SQL_TRACE(sql_trace => FALSE);

# 基本構文: tkprof <トレースファイル> <出力ファイル> [オプション]
tkprof orcl_ora_12345.trc output.txt

# sort オプション: ボトルネック SQL を先に表示する
# sort=fchela: 経過時間（elapsed）の降順で並べる → 遅い SQL を先に見られる
# sort=prsela: PARSE の経過時間の降順
# sort=exeela: EXECUTE の経過時間の降順
tkprof orcl_ora_12345.trc output.txt sort=fchela

# sys=no: SYS（内部処理）の SQL を除外して見やすくする
tkprof orcl_ora_12345.trc output.txt sort=fchela sys=no

# explain オプション: EXPLAIN PLAN を取得して実行計画を出力に含める
tkprof orcl_ora_12345.trc output.txt sort=fchela sys=no     explain=username/password@ORCL

# aggregate=yes（デフォルト）: 同一 SQL の統計を集計する
# aggregate=no: 実行のたびに別々に記録する
tkprof orcl_ora_12345.trc output.txt sort=fchela sys=no aggregate=no

# Oracle 12c 以降: adrci コマンドでトレースファイルを確認する
# adrci> show tracefile
# adrci> show trace <tracefilename>

# tkprof 出力の典型的なフォーマット（抜粋）
SELECT e.employee_id, e.last_name, d.department_name
FROM   employees e
JOIN   departments d ON e.department_id = d.department_id
WHERE  e.salary > :1

call     count       cpu    elapsed       disk      query    current        rows
-------- ------  -------- ---------- -------- ---------- ----------  ----------
Parse        1      0.01       0.02        0          0          0           0
Execute    100      0.05       0.10        0          0          0           0
Fetch      100      2.30       5.80      200      50000          0        2000
-------- ------  -------- ---------- -------- ---------- ----------  ----------
total      201      2.36       5.92      200      50000          0        2000

Misses in library cache during parse: 1      ← ハードパース発生
Optimizer mode: ALL_ROWS
Parsing user id: 42  (APP_USER)

# -----------------------------------------------
# 各列の意味:
# count   : 操作の実行回数（Fetch が多い → N+1 問題の可能性）
# cpu     : CPU 使用時間（秒）
# elapsed : 実際の経過時間（秒）。cpu より大きい場合は待機が多い
# disk    : 物理読み取りブロック数（多い → テーブルフルスキャンや I/O ボトルネック）
# query   : 一貫性読み取りブロック数（論理読み取り）
# current : カレントモード読み取りブロック数（DML で多い）
# rows    : 処理した行数

# ポイントの見方:
# ① elapsed >> cpu → 待機イベント（I/O・ロック）が原因で遅い
# ② Parse count が多い → バインド変数不使用によるハードパースが多発している
# ③ disk が多い → 物理 I/O が多い。インデックスが効いていない可能性
# ④ Fetch count が Execute count の数倍 → ArraySize が小さい・N+1 問題
# ⑤ "Misses in library cache during parse: N" → ハードパースが N 回発生

-- level 8 または 12 でトレースを取得した場合、以下のような待機イベント情報が出力される

-- Elapsed times include waiting on following events:
--   Event waited on                      Times   Max. Wait  Total Waited
--   ------------------------------------------- ----------  ------------
--   db file sequential read                 150        0.05          1.20
--   db file scattered read                   20        0.30          2.10
--   latch: cache buffers chains               5        0.01          0.02
--   enq: TX - row lock contention             2        3.00          5.50

-- db file sequential read: インデックス読み取りの単一ブロック I/O
-- db file scattered read : フルスキャンの複数ブロック I/O（多い場合は全件スキャン疑い）
-- latch: 内部競合（通常は少ない）
-- enq: TX - row lock contention: 行ロック競合（長時間の場合は接続先セッションのロック調査が必要）
-- → 待機の合計が elapsed に近い場合は CPU でなく待機が主因

-- 現在セッションで SQL Trace が有効かどうかを確認する
SELECT value FROM V$PARAMETER WHERE name = 'sql_trace';
-- FALSE: システムレベルは無効（ALTER SESSION で個別に有効にしている場合は別）

-- 現在有効なモニタリング設定を確認する（DBMS_MONITOR で設定したもの）
SELECT * FROM DBA_ENABLED_TRACES;
-- TYPE: SESSION / SERVICE / SERVICE_MODULE / SERVICE_MODULE_ACTION
-- WAITS: YES/NO
-- BINDS: YES/NO

-- システム全体で SQL Trace を有効にする（重大なパフォーマンス影響があるため注意）
ALTER SYSTEM SET SQL_TRACE = TRUE;   -- 本番環境では使用しない
ALTER SYSTEM SET SQL_TRACE = FALSE;  -- 忘れずに元に戻す

-- トレースファイルが増えすぎた場合のサイズ制限
-- MAX_DUMP_FILE_SIZE でトレースファイルの最大サイズを設定する
ALTER SESSION SET MAX_DUMP_FILE_SIZE = '100M';   -- 100MB でトレースを打ち切る
-- または
ALTER SYSTEM SET MAX_DUMP_FILE_SIZE = '500M';    -- システム全体のデフォルト