OracleでSQL実行の内部処理の見える化 その１

DBAを経て、今はJavaのWebアプリの障害対応や見える化を行っている、白石です。

今回は、Oracleデータベースで長時間実行中の操作が、今何をしていて、いつ終わるのかを調査する方法を紹介します。

SQLやPLSQLバッチを実行したけど、なかなか終わらない時ありますよね。
いつ頃終わるのかある程度分かる方法があります。

6秒以上かかっているSQLの操作の残り処理時間の目安の取得
以下のSQLをディクショナリにアクセスできるユーザで実行します。

Oracleのバージョンについては、10gR2、11R2g、12cで使えることは確認しています。
参考URL：Oracle12cマニュアル

SELECT /* vsession_longops */
      TO_CHAR(DECODE(SOFAR, 0, 0, ROUND(ELAPSED_SECONDS*(TOTALWORK-SOFAR) /SOFAR /60, 1) ), '999990.00') AS "残り分数"
     ,TO_CHAR(DECODE(SOFAR, 0, 0, ROUND(ELAPSED_SECONDS*(TOTALWORK-SOFAR) /SOFAR) ), '999990.00') AS "残り秒数"
     ,TO_CHAR(ROUND(ELAPSED_SECONDS/60, 1), '999990.00') AS "経過分数"
     ,TO_CHAR(ELAPSED_SECONDS, '999990.00') AS "経過秒数"
     ,TO_CHAR(START_TIME, 'MM/DD HH24:MI:SS') AS "開始時刻 "
     ,DECODE(
        TARGET_DESC
       ,NULL ,DECODE(
                TARGET
               ,NULL ,OPNAME
               ,OPNAME||' - '||TARGET )
       ,DECODE(
          TARGET
         ,NULL, OPNAME||' : '||TARGET_DESC
         ,OPNAME||' : '||TARGET_DESC||' - '||TARGET )
      ) AS "操作"
     ,TO_CHAR(ROUND(SOFAR/DECODE(NVL(ELAPSED_SECONDS, 0), 0, 1, ELAPSED_SECONDS)*8192/1024/1024, 1), '99999990.00') AS "Avg MB/s"
     ,TO_CHAR(SOFAR, '99999990') AS "終了作業単位"
     ,TO_CHAR(TOTALWORK, '99999990') AS "作業単位の合計"
     ,SQL_ID,UNITS AS "測定単位"
     ,SID,SERIAL#
 FROM V$SESSION_LONGOPS
WHERE 1=1
   -- AND USERNAME = USER /* 調査対象のスキーマ指定 USERはログインユーザの文字列に展開される */
   -- AND SOFAR < TOTALWORK /* この条件を有効にすると処理中のレコードのみ取れる */
ORDER BY CASE WHEN SOFAR < TOTALWORK THEN 0 ELSE 1 END,START_TIME DESC;

※ブロックサイズは8KBだと仮定しています。
XXX_TABLEをフルスキャンするSQLを実行中だと仮定しています。

実行結果　※値は適当に設定しています。

行番号	残り分数	残り秒数	経過分数	経過秒数	開始時刻	操作	Avg MB/s
1	2.00	121.00	2.40	141.00	02/12 10:05:04	Table Scan - XXX_TABLE	107.50
2	0.00	0.00	4.70	281.00	02/12 08:05:03	Table Scan - XXX_TABLE	100.20

表の続き

行番号	終了作業単位	作業単位の合計	SQL_ID	測定単位	SID	SERIAL#
1	1939378	3605408	c56kp30rw0nfj	Blocks	226	9701
2	3605408	3605408	8ky7bjnrq3m57	Blocks	148	1185

実行結果の説明をします。
上に表示されているものほど新しく実行された作業になるようにソートしています。

1行目は、今実行中のXXX_TABLEをフルスキャンする作業で、2.40分経過しており、残り2.00分かかる見込みであることを表しています。
もう一度上記のSQLを実行すると残り時間が減少しているはずです。
この残り時間は、作業単位の合計と終了作業単位と経過秒数を元に計算しています。

注意するのは、ここで確認できる操作は、SQL全体の処理を表しているわけでは無いということです。
SQLの実行計画の１つ１つの操作です。
また、全ての操作が出力されるのではなく、6秒以上かかった操作のみしか出力されません。

この例の様にテーブルフルスキャンの場合は6秒以上かかることも多く、抽出できますが、
他の例としてネステッドループをしてINDEXスキャンを複数回長時間繰り返しているものは、一つ一つの操作が6秒以上かからなければ何も出力されません。