[20260522]测试使用dbms_profiler.txt
--//使用dbms_profiler主要目的监测PL/SQL性能，自己从来没有使用过，看别人的例子，重复测试并做一个笔记。
--//参考链接：http://fritshoogland.wordpress.com/2012/11/26/profiling-plsql-with-dbms_profiler/
1.环境：
SCOTT@book01p> @ ver2
==============================
PORT_STRING : x86_64/Linux 2.4.xx
VERSION : 21.0.0.0.0
BANNER : Oracle Database 21c Enterprise Edition Release 21.0.0.0.0 - Production
BANNER_FULL : Oracle Database 21c Enterprise Edition Release 21.0.0.0.0 - Production
Version 21.3.0.0.0
BANNER_LEGACY : Oracle Database 21c Enterprise Edition Release 21.0.0.0.0 - Production
CON_ID : 0
PL/SQL procedure successfully completed.
2.执行proftab.sql脚本：
SCOTT@book01p> @?/rdbms/admin/proftab.sql
drop table plsql_profiler_data cascade constraints
*
ERROR at line 1:
ORA-00942: table or view does not exist
drop table plsql_profiler_units cascade constraints
*
ERROR at line 1:
ORA-00942: table or view does not exist
drop table plsql_profiler_runs cascade constraints
*
ERROR at line 1:
ORA-00942: table or view does not exist
drop sequence plsql_profiler_runnumber
*
ERROR at line 1:
ORA-02289: sequence does not exist
Table created.
Comment created.
Table created.
Comment created.
Table created.
Comment created.
Sequence created.
--//仔细看脚本很简单就是建立3个表，如果不需要就是删除3个表以及1个sequence。
--//drop table plsql_profiler_data cascade constraints;
--//drop table plsql_profiler_units cascade constraints;
--//drop table plsql_profiler_runs cascade constraints;
--//drop sequence plsql_profiler_runnumber;
3.测试：
--//参考链接：http://fritshoogland.wordpress.com/2012/11/26/profiling-plsql-with-dbms_profiler/
-- script: gtt_and_collection.sql
-- setup
set serveroutput on;
create global temporary table gtt ( col1 number, col2 varchar2(10) ) on commit preserve rows;
create or replace procedure insert_example is
nr_to_loop number:=1000000;
nr number:=0;
type col_type is table of gtt%ROWTYPE;
col col_type:=col_type();
begin
dbms_profiler.start_profiler('profiler run '||to_char(sysdate,'yyyymmddhh24mi'));
dbms_output.put_line('Start: '||to_char(sysdate,'hh24:mi:sssss'));
for nr in 1..nr_to_loop loop
/* gtt */
insert into gtt (col1, col2) values ( nr, 'AABBCCDDEE' );
/* collection */
col.extend;
col(nr).col1 := nr;
col(nr).col2 := 'AABBCCDDEE';
end loop;
commit;
dbms_output.put_line('Stop: '||to_char(sysdate,'hh24:mi:sssss'));
dbms_profiler.stop_profiler;
end;
/
-- execute test
exec insert_example;
-- clean up
--drop procedure insert_example;
truncate table gtt;
drop table gtt;
--//已经写在脚本里面：
--//dbms_profiler.start_profiler('profiler run '||to_char(sysdate,'yyyymmddhh24mi'));
--//dbms_profiler.stop_profiler;
SCOTT@book01p> set serveroutput on;
SCOTT@book01p> exec insert_example;
Start: 09:42:34972
Stop: 09:43:34998
PL/SQL procedure successfully completed.
--//基本上需要1分钟完成测试。
4.分析：
$ cat test_profiler.sql
COL owner FORMAT a16
COL name FORMAT a20
COL line FORMAT 9999
COL source FORMAT a88 WORD_WRAP
COL occurances FORMAT 9999999
COL tot_time_s FORMAT 999,999,990.999
COL run_comment FORMAT a40
COL pct FORMAT 999
SELECT runid, run_date, run_comment FROM plsql_profiler_runs;
SELECT u.unit_owner OWNER
,u.unit_name NAME
,d.line# LINE
, (SELECT text
FROM all_source
WHERE TYPE IN ('PACKAGE BODY'
,'FUNCTION'
,'PROCEDURE'
,'TRIGGER')
AND name = u.unit_name
AND line = d.line#
AND owner = u.unit_owner
AND TYPE = u.unit_type)
SOURCE
,d.total_occur OCCURANCES
, (d.total_time / 1000000000) TOT_TIME_S
,d.total_time / r.run_total_time * 100 "PCT"
FROM plsql_profiler_runs r, plsql_profiler_units u, plsql_profiler_data d
WHERE r.runid = &&runid
AND r.runid = u.runid
AND r.runid = d.runid
AND d.unit_number = u.unit_number
AND (d.total_time / 1000000000) > 1 --more than 1 second
ORDER BY tot_time_s
/
select (run_total_time/1000000000) tot_time_s from plsql_profiler_runs where runid=&runid;
SCOTT@book01p> @ test_profiler.sql
RUNID RUN_DATE RUN_COMMENT
---------- ------------------- ----------------------------------------
1 2026-05-22 16:04:51 profiler run 202605221604
Enter value for runid: 1
OWNER NAME LINE SOURCE OCCURANCES TOT_TIME_S PCT
---------- -------------------- ----- ---------------------------------------------------------------------------------------- ---------- ---------------- ----
SCOTT INSERT_EXAMPLE 15 col.extend; 1000000 1.348 5
SCOTT INSERT_EXAMPLE 12 insert into gtt (col1, col2) values ( nr, 'AABBCCDDEE' ); 1000000 23.903 90
TOT_TIME_S
----------------
26.632
--//注解：AND (d.total_time / 1000000000) > 1 ，加入line排序字段。
SCOTT@book01p> @ test_profiler.sql
RUNID RUN_DATE RUN_COMMENT
---------- ------------------- ----------------------------------------
1 2026-05-22 16:04:51 profiler run 202605221604
OWNER NAME LINE SOURCE OCCURANCES TOT_TIME_S PCT
---------- -------------------- ----- ---------------------------------------------------------------------------------------- ---------- ---------------- ----
SCOTT INSERT_EXAMPLE 1 procedure insert_example is 0 0.000 0
SCOTT INSERT_EXAMPLE 2 nr_to_loop number:=1000000; 0 0.000 0
SCOTT INSERT_EXAMPLE 3 nr number:=0; 0 0.000 0
SCOTT INSERT_EXAMPLE 5 col col_type:=col_type(); 0 0.000 0
SCOTT INSERT_EXAMPLE 7 dbms_profiler.start_profiler('profiler run '||to_char(sysdate,'yyyymmddhh24mi')); 0 0.000 0
SCOTT INSERT_EXAMPLE 8 dbms_output.put_line('Start: '||to_char(sysdate,'hh24:mi:sssss')); 1 0.001 0
SCOTT INSERT_EXAMPLE 9 for nr in 1..nr_to_loop loop 1000001 0.055 0
SCOTT INSERT_EXAMPLE 12 insert into gtt (col1, col2) values ( nr, 'AABBCCDDEE' ); 1000000 23.903 90
SCOTT INSERT_EXAMPLE 15 col.extend; 1000000 1.348 5
SCOTT INSERT_EXAMPLE 16 col(nr).col1 := nr; 1000000 0.335 1
SCOTT INSERT_EXAMPLE 17 col(nr).col2 := 'AABBCCDDEE'; 1000000 0.192 1
SCOTT INSERT_EXAMPLE 20 commit; 1 0.031 0
SCOTT INSERT_EXAMPLE 21 dbms_output.put_line('Stop: '||to_char(sysdate,'hh24:mi:sssss')); 1 0.000 0
SCOTT INSERT_EXAMPLE 22 dbms_profiler.stop_profiler; 1 0.000 0
SCOTT INSERT_EXAMPLE 23 end; 0 0.000 0
15 rows selected.
--//基本可以看出循环测试比较多的地方，以及消耗时间比较多的情况。
TOT_TIME_S
----------------
26.632
5.另外的执行方式：
--//也可以放在pl/sql过程的外面，注解dbms_profiler相关行，重新建立存储过程。
create or replace procedure insert_example is
nr_to_loop number:=1000000;
nr number:=0;
type col_type is table of gtt%ROWTYPE;
col col_type:=col_type();
begin
--dbms_profiler.start_profiler('profiler run '||to_char(sysdate,'yyyymmddhh24mi'));
dbms_output.put_line('Start: '||to_char(sysdate,'hh24:mi:sssss'));
for nr in 1..nr_to_loop loop
/* gtt */
insert into gtt (col1, col2) values ( nr, 'AABBCCDDEE' );
/* collection */
col.extend;
col(nr).col1 := nr;
col(nr).col2 := 'AABBCCDDEE';
end loop;
commit;
dbms_output.put_line('Stop: '||to_char(sysdate,'hh24:mi:sssss'));
--dbms_profiler.stop_profiler;
end;
/
SCOTT@book01p> set serveroutput on;
SCOTT@book01p> exec dbms_profiler.start_profiler('profiler run '||to_char(sysdate,'yyyymmddhh24mi'));
PL/SQL procedure successfully completed.
SCOTT@book01p> exec insert_example;
Start: 16:11:58305
Stop: 16:12:58331
PL/SQL procedure successfully completed.
SCOTT@book01p> exec dbms_profiler.stop_profiler
PL/SQL procedure successfully completed.
SCOTT@book01p> define runid=2
SCOTT@book01p> @ test_profiler.sql
RUNID RUN_DATE RUN_COMMENT
---------- ------------------- ----------------------------------------
1 2026-05-22 16:04:51 profiler run 202605221604
2 2026-05-22 16:11:41 profiler run 202605221611
OWNER NAME LINE SOURCE OCCURANCES TOT_TIME_S PCT
---------------- -------------------- ----- ---------------------------------------------------------------------------------------- ---------- ---------------- ----
SCOTT INSERT_EXAMPLE 1 procedure insert_example is 0 0.000 0
SCOTT INSERT_EXAMPLE 2 nr_to_loop number:=1000000; 1 0.000 0
SCOTT INSERT_EXAMPLE 3 nr number:=0; 1 0.000 0
SCOTT INSERT_EXAMPLE 5 col col_type:=col_type(); 1 0.000 0
SCOTT INSERT_EXAMPLE 8 dbms_output.put_line('Start: '||to_char(sysdate,'hh24:mi:sssss')); 1 0.000 0
SCOTT INSERT_EXAMPLE 9 for nr in 1..nr_to_loop loop 1000001 0.052 0
SCOTT INSERT_EXAMPLE 12 insert into gtt (col1, col2) values ( nr, 'AABBCCDDEE' ); 1000000 23.709 72
SCOTT INSERT_EXAMPLE 15 col.extend; 1000000 1.374 4
SCOTT INSERT_EXAMPLE 16 col(nr).col1 := nr; 1000000 0.329 1
SCOTT INSERT_EXAMPLE 17 col(nr).col2 := 'AABBCCDDEE'; 1000000 0.194 1
SCOTT INSERT_EXAMPLE 20 commit; 1 0.001 0
SCOTT INSERT_EXAMPLE 21 dbms_output.put_line('Stop: '||to_char(sysdate,'hh24:mi:sssss')); 1 0.000 0
SCOTT INSERT_EXAMPLE 23 end; 1 0.036 0
18 rows selected.
TOT_TIME_S
----------------
32.925
SELECT
runid
,unit_number
,unit_type
,unit_owner
,unit_name
,to_char(unit_timestamp,'yyyy-mm-dd hh24:mi:ss')
,total_time
,spare1
,spare2
FROM plsql_profiler_units
RUNID UNIT_NUMBER UNIT_TYPE UNIT_OWNER UNIT_NAME TO_CHAR_UNIT_TIMEST TOTAL_TIME SPARE1 SPARE2
---------- ----------- ---------------- ------------ -------------- ------------------- ---------- ---------- ----------
1 1 PROCEDURE SCOTT INSERT_EXAMPLE 2026-05-22 16:04:33 0
2 1 ANONYMOUS BLOCK
2 2 ANONYMOUS BLOCK
2 3 ANONYMOUS BLOCK
2 4 PROCEDURE SCOTT INSERT_EXAMPLE 2026-05-22 16:09:18 0
2 5 ANONYMOUS BLOCK
2 6 ANONYMOUS BLOCK
7 rows selected.
--//看RUNID=2的信息，就明白为什么前面在procedure insert_example is与nr_to_loop number:=1000000;出现
6.继续：
--//修改commit在循环体内。
create or replace procedure insert_example is
nr_to_loop number:=1000000;
nr number:=0;
type col_type is table of gtt%ROWTYPE;
col col_type:=col_type();
begin
dbms_profiler.start_profiler('profiler run '||to_char(sysdate,'yyyymmddhh24mi'));
dbms_output.put_line('Start: '||to_char(sysdate,'hh24:mi:sssss'));
for nr in 1..nr_to_loop loop
/* gtt */
insert into gtt (col1, col2) values ( nr, 'AABBCCDDEE' );
/* collection */
col.extend;
col(nr).col1 := nr;
col(nr).col2 := 'AABBCCDDEE';
commit;
end loop;
dbms_output.put_line('Stop: '||to_char(sysdate,'hh24:mi:sssss'));
dbms_profiler.stop_profiler;
end;
/
SCOTT@book01p> exec insert_example;
Start: 16:29:59352
Stop: 16:30:59437
PL/SQL procedure successfully completed.
SCOTT@book01p> define runid=3
SCOTT@book01p> @ test_profiler.sql
RUNID RUN_DATE RUN_COMMENT
---------- ------------------- ----------------------------------------
1 2026-05-22 16:04:51 profiler run 202605221604
2 2026-05-22 16:11:41 profiler run 202605221611
3 2026-05-22 16:29:12 profiler run 202605221629
OWNER NAME LINE SOURCE OCCURANCES TOT_TIME_S PCT
---------------- -------------------- ----- ---------------------------------------------------------------------------------------- ---------- ---------------- ----
SCOTT INSERT_EXAMPLE 1 procedure insert_example is 0 0.000 0
SCOTT INSERT_EXAMPLE 2 nr_to_loop number:=1000000; 0 0.000 0
SCOTT INSERT_EXAMPLE 3 nr number:=0; 0 0.000 0
SCOTT INSERT_EXAMPLE 5 col col_type:=col_type(); 0 0.000 0
SCOTT INSERT_EXAMPLE 7 dbms_profiler.start_profiler('profiler run '||to_char(sysdate,'yyyymmddhh24mi')); 0 0.000 0
SCOTT INSERT_EXAMPLE 8 dbms_output.put_line('Start: '||to_char(sysdate,'hh24:mi:sssss')); 1 0.000 0
SCOTT INSERT_EXAMPLE 9 for nr in 1..nr_to_loop loop 1000001 0.125 0
SCOTT INSERT_EXAMPLE 12 insert into gtt (col1, col2) values ( nr, 'AABBCCDDEE' ); 1000000 49.029 58
SCOTT INSERT_EXAMPLE 15 col.extend; 1000000 2.100 2
SCOTT INSERT_EXAMPLE 16 col(nr).col1 := nr; 1000000 0.456 1
SCOTT INSERT_EXAMPLE 17 col(nr).col2 := 'AABBCCDDEE'; 1000000 0.296 0
SCOTT INSERT_EXAMPLE 18 commit; 1000000 31.460 37
SCOTT INSERT_EXAMPLE 20 dbms_output.put_line('Stop: '||to_char(sysdate,'hh24:mi:sssss')); 1 0.000 0
SCOTT INSERT_EXAMPLE 21 dbms_profiler.stop_profiler; 1 0.000 0
SCOTT INSERT_EXAMPLE 22 end; 0 0.000 0
15 rows selected.
TOT_TIME_S
----------------
84.652
--//可以看出commit在循环体内执行效率不高。
7.意外插曲：
--//看最后一次执行的显示:
SCOTT@book01p> exec insert_example;
Start: 16:29:59352
Stop: 16:30:59437
PL/SQL procedure successfully completed.
--//3次测试都是类似,start与stop的时间间隔都是60秒上下.而最后1次执行测试总时间是84.652.明显那里存在问题？
SCOTT@book01p> define runid=3
SCOTT@book01p> @ test_profiler.sql
RUNID RUN_DATE RUN_COMMENT
---------- ------------------- ----------------------------------------
1 2026-05-22 16:04:51 profiler run 202605221604
2 2026-05-22 16:11:41 profiler run 202605221611
3 2026-05-22 16:29:12 profiler run 202605221629
....
--//RUNID,Start: 16:29:59352,而RUN_DATE记录确是2026-05-22 16:29:12.
--//实际上仔细看脚本作者原始脚本格式使用sssss，查询官方文档发现sssss表示Seconds past midnight (0-86399).
--//59437-59352 = 85,这样就非常接近了。
$ cat s2hms.sql
column "hh24:mi:ss" format a10
select to_char(to_date(&&1,'sssss'),'hh24:mi:ss') "hh24:mi:ss" from dual;
SCOTT@book01p> @ s2hms 59352
hh24:mi:ss
----------
16:29:12
--//完成可以对上。
--//另外写一篇时间格式的说明.
[20260522]测试使用dbms_profiler.txt
-
lfree
2026-05-24 20:02:27 -
Oracle
- 原创