Oracle10gのSQLチューニングについての検証その４

＜Oracle10gのSQLチューニングについての検証その４＞
～v$sql活用編～
ペンネーム：りん

今年も後少しだということに最近気づいたりんです。こんにちは。
1年は早いですね…ラストスパート頑張りましょう。

さて、今回は、PLSQL_EXEC_TIMEについての検証です。
マニュアルには、PL/SQLの実行時間と記載されていますが…
なんの値なんでしょうか？早速見てみましょう。

SQL> begin
  2      for cnt in 1..10000 loop
  3          update test_table set value = cnt where id = cnt;
  4          commit;
  5      end loop;
  6  end;
  7  /

PL/SQLプロシージャが正常に完了しました。

実行後のv$sqlビューの情報を確認します。

SQL> select sql_text, cpu_time, elapsed_time, plsql_exec_time from
  2  v$sql where sql_text like 'begin%update test_table%';

SQL_TEXT
--------------------------------------------------------------------------------
begin     for cnt in 1..10000 loop         update test_table set value = cnt whe
re id = cnt;     end loop;     commit; end;

CPU_TIME ELAPSED_TIME PLSQL_EXEC_TIME
---------- ------------ ---------------
  37747674     37747674          326584

以下、トレース情報です。

=====================
PARSING IN CURSOR #1 len=123 dep=0 uid=0 oct=47 lid=0 tim=1074351234399781
 hv=1054212170 ad='5bb1c764'
begin
    for cnt in 1..10000 loop
        update test_table set value = cnt where id = cnt;
    end loop;
    commit;
end;
END OF STMT
PARSE #1:c=170000,e=169400,p=2,cr=225,cu=0,mis=1,r=0,dep=0,og=1,tim=1074351234399747
BINDS #1:
...
EXEC #1:c=37650000,e=37578274,p=34,cr=230140,cu=10293,mis=0,r=1,dep=0,og=1,
 tim=1074351271978309

CPU_TIMEと、ELAPSED_TIMEについては、PARSEとEXECの合算値のようですが…
326584マイクロ秒はどこから来たんでしょうねぇ
0.32秒…

プロファイラではどのように算出されるのでしょうか
少しプロシージャーを変更してやってみます。

declare
        rc      binary_integer;
        exec_n  number;
begin
        rc := dbms_profiler.start_profiler('Start1','',exec_n);
        for i in 1..10000 loop
                insert into test_table values ( i,i,i,i,
                'データデータデータデータデータデータデータ
                データデータデータデータデータデータデータ
                データデータデータデータデータデータデータ
                データデータデータデータデータデータデータ
                データ');←1行です。
                commit;
        end loop;
        dbms_output.put_line ( ' Exec Number : ' || exec_n );
        rc := dbms_profiler.stop_profiler;
end;
/

SQL> select sql_text,plsql_exec_time,cpu_time,elapsed_time from
  2  v$sql where plsql_exec_time != 0;

SQL_TEXT
------------------------------------------------------------
declare  rc binary_integer;  exec_n number; begin  rc := dbm
s_profiler.start_profiler('Start1','',exec_n);  for i in 1..
10000 loop   insert into test_table values ( i,i,i,i,'データ
データデータデータデータデータデータデータデータデータデータ
データデータデータデータデータデータデータデータデータデータ
データデータデータデータデータデータデータデータ');   commit
;  end loop;  dbms_output.put_line ( ' Exec Number : ' || ex
ec_n );  rc := dbms_profiler.stop_profiler; end;

PLSQL_EXEC_TIME   CPU_TIME ELAPSED_TIME
--------------- ---------- ------------
        1545390   23250000     42638849


  1  select
  2     runid,
  3     sum(total_time)/1000 total_time_micro
  4  from
  5     plsql_profiler_data
  6  where
  7     runid=5
  8  group by
  9*    runid
SQL> /

     RUNID TOTAL_TIME_MICRO
---------- ----------------
         5         38701834

やはり、PLSQL_EXEC_TIMEは全部の実行時間というわけではなさそうです。
CPU_TIMEよりも短い時間で終了しているようですし…
もう1度、dbms_profilerを除外してやってみましょう

declare
        rc      binary_integer;
        exec_n  number;
begin
        for i in 1..10000 loop
                insert into test_table values (
                i,i,i,i,
                'データデータデータデータデータデータ
                データデータデータデータデータデータ
                データデータデータデータデータデータ
                データデータデータデータデータデータ
                データデータデータデータデータ');
                commit;
         end loop;
end;
/

SQL> select sql_text,plsql_exec_time,cpu_time,elapsed_time from
  2  v$sql where sql_text like 'declare%';

SQL_TEXT
------------------------------------------------------------
declare  rc binary_integer;  exec_n number; begin  for i in
1..10000 loop   insert into test_table values ( i,i,i,i,'デ
ータデータデータデータデータデータデータデータデータデータデ
ータデータデータデータデータデータデータデータデータデータデ
ータデータデータデータデータデータデータデータデータ');   co
mmit;  end loop; end;

PLSQL_EXEC_TIME   CPU_TIME ELAPSED_TIME
--------------- ---------- ------------
        1195325   21790000     38434761

では、出力したトレースファイルから
PL/SQLブロックに記述しているINSERT文とCOMMITを除外してみると、再帰SQL
文の合計経過時間は977448マイクロ秒で、似たような数字になります。
PLSQL_EXEC_TIMEとは、PLSQLブロックで記述したSQL文以外のロジックでの
実行時間ということになりそうですね。

では、再帰SQL文の合計値ということなのでしょうか？
試しに、以下のPLSQLブロックを作成して実行してみます。

declare
 v_test	number;
begin
 for i in 1..10000 loop
  v_test := v_test + 1;
 end loop;
end;
/

V$SQLの結果は以下の通りです。

SQL> select sql_text,plsql_exec_time,cpu_time,elapsed_time from
  2  v$sql where sql_text like 'declare%';

SQL_TEXT
------------------------------------------------------------
declare  v_test number; begin  for i in 1..100000 loop   v_t
est := v_test + 1;  end loop; end;

PLSQL_EXEC_TIME   CPU_TIME ELAPSED_TIME
--------------- ---------- ------------
          11221      20000        98299

このPL/SQLブロックのトレースを見ると…

Parsing…86892マイクロ秒
Exec…11407マイクロ秒

でした。

当然の結果ですが、PLSQL_EXEC_TIMEとトレースのEXECの大きな開きはありま
せんでした。ELAPSED_TIMEには、ParsingやEXEC、WAITも含まれますが
PLSQL_EXEC_TIMEというのは、PL/SQLブロックのロジックを実行していた
純粋な時間…つまり、SQLの実行時間やWAITなどを抜いた値のようですね。

…ということは、Oracle10gから追加されたWAIT_TIMEやEXEC_TIMEなどの
カラムは、SQL文以外の時間であると考えると、すっきりするかもしれません。

4回に渡って検証した今回のメルマガのまとめとしては
Oracle10gからV$SQLに追加されたApplication_Wait_TimeやPLSQL_EXEC_TIMEは
SQL文の実行以外にかかった時間を表すもの…ということですね。
どこにチューニングポイントがあるのか？を、ざっくり判断する材料に
使えそうです。

寒くなってきました茅ヶ崎にて

Oracle10gのSQLチューニングについての検証 その４

Oracle10gのSQLチューニングについての検証その４