PL/SQL のボトルネックを特定する方法

Oracle のパフォーマンスチューニングで役立つ（実務で実際に役立った）ネタを紹介していきます。

PL/SQL の ボトルネックを特定するには

SQL のボトルネックを特定する方法は色々ありますが、PL/SQL のボトルネックを特定する方法はご存知でしょうか？

DBMS_PROFILER を使用することで、PL/SQL 実行時のステップ毎の実行時間を測定できるようになります。
これにより、PL/SQL のソースのどのステップで実行に時間が掛かっているか特定することができます。

[参考] DBMS_PROFILER -Oracle Database PL/SQLパッケージおよびタイプ・リファレンス
https://docs.oracle.com/cd/E57425_01/121/ARPLS/d_profil.htm

DBMS_PROFILER の使用例

以下、実際に DBMS_PROFILER の使用例を記載します。

なお SCSK 株式会社は、本ドキュメントの使用の結果生じるいかなる損害についても、責任を負いかねますのでご了承ください。本番環境で実施する際には、十分検証してからの実施を推奨します。

1. DBMS_PROFILERパッケージのインストール (9i以前)

環境変数 ORACLE_HOME/rdbms/admin/profload.sql を実行することで、DBMS_PROFILER パッケージをインストールできます。

なお 10g 以降のバージョンではデータベース作成時に DBMS_PROFILER が自動的にロードされるようになりました。
そのため、10g 移行では明示的に profload.sql を実行する必要はありません。

bash-3.2$ sqlplus / as sysdba
SQL> @$ORACLE_HOME/rdbms/admin/profload.sql

パッケージが作成されました。

権限付与が成功しました。

シノニムが作成されました。

ライブラリが作成されました。

パッケージ本体が作成されました。

Testing for correct installation
SYS.DBMS_PROFILER successfully loaded.

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

2. プロファイラが使用するテーブルを作成

bash-3.2$ sqlplus test/test
SQL> @$ORACLE_HOME/rdbms/admin/proftab.sql

3. テスト用テーブルを作成

SQL> @cr_sample_tbl.sql

SQL> create table sample_tbl
　2  (
　3 　id number,
　4 　cola varchar2(100)
　5  )
　6  ;

SQL> @sample_proc.sql
SQL> CREATE OR REPLACE PROCEDURE sample_proc IS
　2  　cnt number:=0;
　3  BEGIN
　4　　FOR i IN 1..500000 LOOP
　5 　　insert into sample_tbl values (i,'aaaaaaaaaa');
　6 　 END LOOP;
　7 　 commit;
　8 　 select count(*) into cnt from sample_tbl;
　9 　 dbms_output.put_line(cnt);
 10　END;
 11　/

プロシージャが作成されました。
経過: 00:00:00.09

SQL> show error
エラーはありません。

5. テスト用プロシージャの実行

SQL> @exec_sample_proc.sql
SQL> declare
　2　　err number;
　3　begin
　4　　err:=DBMS_PROFILER.START_PROFILER (to_char(sysdate,'dd-Mon-YYYY hh:mi:ss'));
　5
　6　　sample_proc;
　7
　8　　err:=DBMS_PROFILER.STOP_PROFILER ;
　9 end;
 10 /
500000

PL/SQLプロシージャが正常に完了しました。
経過: 00:01:23.89

6. プロファイリング結果の取得

SQL> @show_profiling_result.sql
SQL> column RUN_COMMENT format a40
SQL> select runid, run_date, RUN_COMMENT from plsql_profiler_runs order by runid;

　　RUNID RUN_DATE RUN_COMMENT
--------- -------- ------------------------
　　　　1 18-05-10 10-5月 -2018 12:48:14
　　　　2 18-05-10 10-5月 -2018 12:56:14
　　　　3 18-05-10 10-5月 -2018 01:01:41
　　　　4 18-05-10 10-5月 -2018 01:13:18

経過: 00:00:00.01

SQL> column unit_name format a15
SQL> column occured format 999999
SQL> column line# format 99999
SQL> column tot_time format 999.999999
SQL> column text format a60

SQL> select
  2 　　p.unit_name
　3 　, p.occured
　4 　, p.tot_time
　5 　, p.line# line
　6 　, substr(s.text, 1,75) text
　7 　from
　8 　　(select
　9 　　　　u.unit_name
 10 　　　, d.TOTAL_OCCUR occured
 11 　　　, (d.TOTAL_TIME/1000000000) tot_time
 12 　　　, d.line#
 13 　　from
 14 　　　　plsql_profiler_units u
 15 　　　, plsql_profiler_data d
 16 　　where
 17 　　　　d.RUNID=u.runid
 18　　 and d.UNIT_NUMBER = u.unit_number
 19　　 and d.TOTAL_OCCUR >0
 20 　　and u.unit_name = '&proc_name'
 21 　　and u.runid = &id
 22 　　) p
 23 　, user_source s
 24 where
 25 　p.unit_name = s.name(+)
 26 and p.line# = s.line (+)
 27 order by
 28 p.unit_name, p.line#;

proc_nameに値を入力してください: SAMPLE_PROC ←対象のプロシージャ名を指定
旧 20: and u.unit_name = '&proc_name'
新 20: and u.unit_name = 'SAMPLE_PROC'
idに値を入力してください: 4 ←対象のrunidを指定
旧 21: and u.runid = &id
新 21: and u.runid = 4


UNIT_NAME　　　　OCCURED TOT_TIME　　LINE　TEXT
---------------- ------- ----------- ----- ------------------------------------------------------------
SAMPLE_PROC　　　　　　1　　 .000001 　　2 cnt number:=0;
SAMPLE_PROC　　　 500001　　 .305684 　　4 FOR i IN 1..500000 LOOP
SAMPLE_PROC　　　 500000　 82.493505 　　5 insert into sample_tbl values (i,'aaaaaaaaaa'); 　★
SAMPLE_PROC　　　　　　1　　 .018485 　　7 commit; 
SAMPLE_PROC　　　　　　1　　 .070546 　　8 select count(*) into cnt from sample_tbl;
SAMPLE_PROC　　　　　　1　　 .000718 　　9 dbms_output.put_line(cnt);
SAMPLE_PROC　　　　　　1　　 .000015 　 10 END;

7行が選択されました。

経過: 00:00:00.18

上記の結果から、Line:5 の insert 文で大半の時間を使用していることがわかりました。

このようにステップごとの実行回数や実行時間が測定できるので、ソースのどこに原因がどこにあるか特定できるようになります。