• Oracle Database
• 2013.12.09
• 渡部 亮太

waitprof.sql from TPT Scripts : Session Wait Profiler

このエントリは (全部俺) Oracle ACE Director Tanel Poder Advent Calendar 2013 9日目の記事です。

http://co-sol.jp/techdb/2013/12/advanced-oracle-troubleshooting-guide-part-2-no-magic-is-needed-systematic-approach-will-do-ja.html で使われていたwaitprof.sqlについて説明を記載します。

使用方法

waitprof.sqlの冒頭のコメント部分に書いてある通りです。

-- Usage:       @waitprof <print|noprint> <sid> <e[123s]> <#samples>
--
--                  <print|noprint>
--                              - whether to print P2,P3,SEQ# values or not
--
--                  <sid>       - session ID of session to sample
--
--                  <[e123s]>   - sample grouping
--                      e - group by event name
--                      1 - group by P1 of v$session_wait event
--                      2 - group by P2
--                      3 - group by P3
--                      s - group by SEQ#
--
--                  <#samples>  - how many samples to take (a modern CPU can take
--                                tens of thousands to low hundreds of k samples
--                                per second)
--  Examples:
--              @waitprof noprint 350 e 1000000   -- take million samples, group by event only
--              @waitprof print 350 e123 500000 -- take 500k samples, group by event,p1,p2,p3
--              @waitprof print 350 e3 1000000  -- take million samples, group by event,p3
--              @waitprof print 350 es 1000000  -- take million samples, group by event,seq#

waitprof.sqlのサンプリング実装

waitprof.sqlではDBMS_LOCK.SLEEPなどのPL/SQLを使用せず、SQLだけでサンプリング機能を実装しています。 その仕組みはwaitprof.sqlのWITH句にある3つの副問合せブロックt1, samples, t2にあります。

waitprof.sqlのWITH句の箇所を抜粋します。

WITH 
    t1 AS (SELECT hsecs FROM v$timer),←(*4)
    samples AS (
    SELECT /*+ ORDERED NO_MERGE USE_NL(sw.gv$session_wait.s) */ ←(*3)
        s.sid sw_sid,
        CASE WHEN sw.state = 'WAITING' THEN 'WAITING' ELSE 'WORKING' END AS state,
        CASE WHEN sw.state = 'WAITING' THEN event ELSE 'On CPU / runqueue' END AS sw_event,
        CASE WHEN sw.state = 'WAITING' AND '&_swp_p123' LIKE '%1%' THEN sw.p1text || '= ' || CASE WHEN (LOWER(sw.p1text) LIKE '%addr%' OR sw.p1 >= 536870912) THEN RAWTOHEX(sw.p1raw) ELSE TO_CHAR(sw.p1) END ELSE NULL END swp_p1,
        CASE WHEN sw.state = 'WAITING' AND '&_swp_p123' LIKE '%2%' THEN sw.p2text || '= ' || CASE WHEN (LOWER(sw.p2text) LIKE '%addr%' OR sw.p2 >= 536870912) THEN RAWTOHEX(sw.p2raw) ELSE TO_CHAR(sw.p2) END ELSE NULL END swp_p2,
        CASE WHEN sw.state = 'WAITING' AND '&_swp_p123' LIKE '%3%' THEN sw.p3text || '= ' || CASE WHEN (LOWER(sw.p3text) LIKE '%addr%' OR sw.p3 >= 536870912) THEN RAWTOHEX(sw.p3raw) ELSE TO_CHAR(sw.p3) END ELSE NULL END swp_p3,
        CASE WHEN LOWER('&_swp_p123') LIKE '%s%' THEN sw.seq# ELSE NULL END seq#,
        COUNT(*) total_samples,
        COUNT(DISTINCT seq#) dist_events,
        TRUNC(COUNT(*)/COUNT(DISTINCT seq#)) average_samples
    FROM
        ( SELECT /*+ NO_MERGE */ TO_NUMBER(&_swp_sid) sid FROM        ←(*1)
            (SELECT rownum r FROM dual CONNECT BY ROWNUM <= 1000) a,  ←(*1)
            (SELECT rownum r FROM dual CONNECT BY ROWNUM <= 1000) b,  ←(*1)
            (SELECT rownum r FROM dual CONNECT BY ROWNUM <= 1000) c   ←(*1)
          WHERE ROWNUM <= &_swp_samples ←(*2)                        ←(*1)
        ) s,
        v$session_wait sw
    WHERE
        s.sid = sw.sid
    GROUP BY
        s.sid,
        CASE WHEN sw.state = 'WAITING' THEN 'WAITING' ELSE 'WORKING' END,
        CASE WHEN sw.state = 'WAITING' THEN event ELSE 'On CPU / runqueue' END,
        CASE WHEN sw.state = 'WAITING' AND '&_swp_p123' LIKE '%1%' THEN sw.p1text || '= ' || CASE WHEN (LOWER(sw.p1text) LIKE '%addr%' OR sw.p1 >= 536870912) THEN RAWTOHEX(sw.p1raw) ELSE TO_CHAR(sw.p1) END ELSE NULL END,
        CASE WHEN sw.state = 'WAITING' AND '&_swp_p123' LIKE '%2%' THEN sw.p2text || '= ' || CASE WHEN (LOWER(sw.p2text) LIKE '%addr%' OR sw.p2 >= 536870912) THEN RAWTOHEX(sw.p2raw) ELSE TO_CHAR(sw.p2) END ELSE NULL END,
        CASE WHEN sw.state = 'WAITING' AND '&_swp_p123' LIKE '%3%' THEN sw.p3text || '= ' || CASE WHEN (LOWER(sw.p3text) LIKE '%addr%' OR sw.p3 >= 536870912) THEN RAWTOHEX(sw.p3raw) ELSE TO_CHAR(sw.p3) END ELSE NULL END,
        CASE WHEN LOWER('&_swp_p123') LIKE '%s%' THEN sw.seq# ELSE NULL END
    ORDER BY
        CASE WHEN LOWER('&_swp_p123') LIKE '%s%' THEN -seq# ELSE total_samples END DESC
),
    t2 AS (SELECT hsecs FROM v$timer)←(*4)
SELECT /*+ ORDERED */

まず、samplesの副問合せブロックを見ます。サンプリング処理の観点では、以下の箇所がポイントになります。

    SELECT /*+ ORDERED NO_MERGE USE_NL(sw.gv$session_wait.s) */ ← (*3)
      : 
    FROM
        ( SELECT /*+ NO_MERGE */ TO_NUMBER(&_swp_sid) sid FROM        ←(*1)
            (SELECT rownum r FROM dual CONNECT BY ROWNUM <= 1000) a,  ←(*1)
            (SELECT rownum r FROM dual CONNECT BY ROWNUM <= 1000) b,  ←(*1)
            (SELECT rownum r FROM dual CONNECT BY ROWNUM <= 1000) c   ←(*1)
          WHERE ROWNUM <= &_swp_samples  ←(*2)                       ←(*1)
        ) s,
        v$session_wait sw
    WHERE
        s.sid = sw.sid
      : 

a, b, c で定義された1000行の結果セットを返すサブクエリを直積結合し、waitprof.sqlの引数で指定されたサンプル数でフィルタしています(*2)。結果として、サンプル数だけ行数のセッションIDの結果セットsが生成されます。

          s   
          ----
       ↑ sid1
       │ sid1
 サンプル sid1
       数 sid1
       │  :  
       ↓ sid1

結果セットs に対してv$session_waitを結合します。ここでのポイントは(*3)の /*+ ORDERED NO_MERGE USE_NL(sw.gv$session_wait.s) */ ヒントです。USE_NLヒント、ORDEREDヒントの働きにより、結果セット s → v$session_wait の順番でネステッドループ結合をすることになります。

上記の通り、結果セットsにはサンプル数の行が含まれ、サンプル数は一般に非常に大きい数であるため、ネステッドループ結合のマッチが非常に大きい回数だけ実行されます。この結合における内部表は、v$session_waitですが、V$ビューであるため、読み取り一貫性は保証されず、アクセスされた時の状態が得られる形になります。このため、時間が経過に従って、得られるセッション状態が異なることになり、サンプリング相当の処理が実行できることになります。

          s         
          ---- 
       ↑ sid1 ⇔ V$SESSION WHERE sid=sid1  @ 00:00:00.000
       │ sid1 ⇔ V$SESSION WHERE sid=sid1  @ 00:00:00.001
 サンプル sid1 ⇔ V$SESSION WHERE sid=sid1  @ 00:00:00.002
       数 sid1 ⇔ V$SESSION WHERE sid=sid1  @ 00:00:00.003
       │  :                       : 
       ↓ sid1 ⇔ V$SESSION WHERE sid=sid1  @ 00:00:01.076

  ※:@はSQLの実行開始時点からの経過時間を示すようイメージしています。

(*4) このsamplesの前後に、(SELECT hsecs FROM v$timer) で定義されるt1, t2の副問合せブロックがあります。 V$TIMERは1/100単位でカウントされる単調増加する数値を保持するV$ビューです。 処理の順序はt1 -> samples -> t2ですので、samplesの処理時間を要すると、t1が評価されるタイミングとt2が評価されるタイミングに若干のタイムラグができてきます。（v$timerもv$session_waitと同様に読み取り一貫性が保証されないため）

面白いHackですが、ある種ビジーループ的な処理なので、CPU時間を多く消費することには注意が必要でしょう。