The DBMS_PROFILER package is similar to a UTLESTAT/UTLBSTAT
for PL/SQL. Just as UTLESTAT and UTLEBSTAT collect database level
statistics for later analysis the DBMS_PROFILER package does the
same for PL/SQL. The package allows you to start, stop and flush
statistics to persistent storage. The DBMS_PROFILER package is
created using the PROFLOAD.SQL script located in the $ORACLE_HOME/rdbms/admin
directory on UNIX and ORACLE_HOME\rdbms\admin directory on NT. The
required storage tables for persistent data retention are created
using the PROFTAB.SQL script co-located with the PROFLOAD.SQL
script. If the data collected by DBMS_PROFILER packages is not
flushed to the persistent tables created with PROFTAB.SQL the
data is erased at the end of the monitoring session.
Data is only flushed when the explicit call to the
flush_data procedure is made or when the stop_profiler function is
executed. To ensure collection of proper statistics put the
application though a complete cycle before invoking the
start_profiler function, otherwise startup noise of the PL/SQL
portions of the application may mask or indicate non-existent
problems.
The profiler gathers the following information
about each line of PL/SQL code:
-
Total elapsed time in execution
-
Number of times line has been executed
-
Minimum and maximum times spent executing
line
Based on the above information the DBA and
developers can concentrate their efforts on the PL/SQL statements
that are the most costly.
DBMS_PROFILER must be installed as the SYS user.
The functions in the DBMS_PROFILER package have
the following return codes:
-
ERROR_PARAM which shows an incorrect
parameter was sent to the function it corresponds to a one (1).
-
ERROR_IO which shows that a data flush
operation failed, usually due to permission or tables not being
present it corresponds to a two (2).
-
ERROR_VERSION which shows there is a mismatch
between the version of profiler and the database it corresponds
to a negative one (-1).
START_PROFILER
The start_profiler function has a single input
variable: run_comment VARCHAR2 which defaults to the value of
SYSDATE. The function starts collection of PL/SQL statistics and
should not be invoked until the application has been run through
once to avoid startup noise. The function returns a BINARY_INTEGER
which will be zero (0) if the call was successful, otherwise it
will relate to one of the standard DBMS_PROFILER error codes.
DBMS_PROFILE.START_PROFILER(run_comment IN VARCHAR2:=SYSDATE)
RETURN BINARY_INTEGER;
STOP_PROFILER
The stop_profiler function has no input variables
and returns a BINARY_INTEGER which will be zero (0) if the call
was successful, otherwise it will relates to one of the standard
DBMS_PROFILER error codes. The stop_profiler flushes statistics to
the pre-defined flush tables and stops PL/SQL statistics
gathering.
DBMS_PROFILER.STOP_PROFILER RETURN BINARY_INTEGER;
FLUSH_DATA
The flush_data function has no input variables and
returns a BINARY_INTEGER that will be zero (0) if the call was
successful, otherwise it will relate to one of the standard
DBMS_PROFILER error codes. The flush_data function flushes
statistics to the pre-defined flush tables. The flush_data
function can be used at anytime during statistics gathering to
provide intermediate looks at PL/SQL statistics. To use FLUSH_DATA
the PROFTAB.SQL script must have been run and the tables available
to the executing user.
DBMS_PROFILE.FLUSH_DATA RETURN BINARY_INTEGER;
GET_VERSION
The get_version procedure gets the version of the
DBMS_PROFILER API to ensure that there isn't a version mismatch.
The procedure GET_VERSION has the following output variables:
-
Major BINARY_INTEGER
-
Minor BINARY_INTEGER
DBMS_PROFILER.GET_VERSION(major VARCHAR2, minor VARCHAR2);
INTERNAL_VERSION_CHECK
The internal version check function verifies that
this version of DBMS_PROFILER will work with the version of the
database. The function has no input variables and returns a
BINARY_INTEGER which will be zero (0) if the call was successful,
otherwise it will relate to one of the standard DBMS_PROFILER
error codes.
DBMS_PROFILER.INTERNAL_VERSION_CHECK RETURNS BINARY_INTEGER;
Example Using
DBMS_PROFILER
In order to use DBMS_PROFILER you must insert
calls to the various functions inside DBMS_PROFILER into your
package. Look at Figure 7 which shows a simple PL/SQL anonymous
block.
declare
x integer;
begin
x:=dbms_profiler.start_profiler('Test Profiler');
DBA_UTILITIES.just_statistics;
x:=dbms_profiler.flush_data;
x:=dbms_profiler.stop_profiler;
end;
/
In listing 1 we start the profiler with the call
to DBMS_PROFILER.START_PROFILER, we then execute the script we
want monitored and the issue an implicit data flush (DBMS_PROFILER.FLUSH_DATA)
and then issue the call to DBMS_PROFILER.STOP_PROFILER to stop the
profiler from collection of data. We probably do not have to issue
the DBMS_PROFILER.FLUSH_DATA since DBMS_PROFILER.STOP_PROFILE
supposedly does this automatically.
The procedure we want to evaluate is contained in
the DBA_UTILITIES package and is called JUST_STATISTICS. The
procedure JUST_STATISTICS gathers various statistics about the
Oracle database and writes them into a temporary file for review.
The results of the operation as gleaned from the
PL/SQL_PROFILER tables is shown in Figure 8.
SQL> col
run_comment format a20
SQL> select runid, run_date, run_total_time, run_comment from
plsql_profiler_runs;
RUNID
RUN_DATE RUN_TOTAL_TIME RUN_COMMENT
--------- --------- -------------- --------------------
1 05-SEP-99 6.802E+11 Test
Profiler
2 05-SEP-99
533133
SQL> col
unit_name format a15
SQL> col unit_type format a15
SQL> column unit_owner format a11
SQL> select runid,unit_number,unit_type,unit_owner, unit_name,
unit_timestamp,
2 total_time from plsql_profiler_units where runid=2;
RUNID
UNIT_NUMBER UNIT_TYPE UNIT_OWNER UNIT_NAME UNIT_TIME
TOTAL_TIME
----- ----------- --------------- ----------- ---------------
--------- ---------- 2 1 ANONYMOUS BLOCK
<anonymous> <anonymous> 00-DECEMB 0
2 2 PACKAGE BODY SYS DBMS_PROFILER
05-SEP-99 0
2 rows selected.
SQL> select
runid,unit_number, line#,total_occur, total_time, min_time,
max_time
2 from
plsql_profiler_data where runid=2
RUNID
UNIT_NUMBER LINE# TOTAL_OCCUR TOTAL_TIME MIN_TIME MAX_TIME
--------- ----------- --------- ----------- ---------- ---------
---------
2 1 4 0 0
0 0
2 1 5 0 0
0 0
2 1 6 1 20157 20157 20157
2 1 7 1 37566
37566 37566
2 2 8 2 125887
4158 121728
2 2 51 2 7301
2917 4383
2 2 57 0 0
0 0
2 2 58 0 0
0 0
2 2 60 1 19431
19431 19431
2 2 65 2 15498
6135 9362
2 2 66 0 0
0 0
2 2 68 1 2001
2001 2001
2 2 73 0 0
0 0
2 2 74 0 0
0 0
2 2 76 0 0
0 0
2 2 82 0 0
0 0
2 2 83 0 0
0 0
17 rows
selected.
Not a lot of information about DBA_UTILITIES shown
is there? Why not? Remember, the calls to DBMS_PROFILER have to be
inside the object being profiled. In this case we placed the calls
inside the PL/SQL anonymous block, but not inside DBA_UTILITIES so
all we profiled was the execution of the PL/SQL block.
Look at Figure 9, it shows the (partial) results
for the same run with the calls to DBMS_PROFILER placed both in
the anonymous PL/SQL block and inside
DBA_UTILITIES.JUST_STATISTICS.
SQL> @test_profiler
SQL> declare
2 x integer;
3 begin
4 x:=dbms_profiler.start_profiler('Test Profiler2');
5 DBA_UTILITIES.just_statistics;
6 x:=dbms_profiler.flush_data;
7 x:=dbms_profiler.stop_profiler;
8 end;
9 /
PL/SQL procedure
successfully completed.
SQL> col
run_comment format a20
SQL> select runid, run_date, run_total_time, run_comment from
plsql_profiler_runs;
RUNID RUN_DATE RUN_TOTAL_TIME RUN_COMMENT
--------- --------- -------------- -----------------
1 05-SEP-99 6.802E+11 Test Profiler
2 05-SEP-99 533133
3 05-SEP-99 1.393E+09 Test Profiler2
4
05-SEP-99 522158
SQL> select
runid,unit_number,unit_type,unit_owner, unit_name, unit_timestamp,
2 total_time from plsql_profiler_units where runid>2;
RUNID
UNIT_NUMBER UNIT_TYPE UNIT_OWNER UNIT_NAME
UNIT_TIME TOTAL_TIME
--------- ----------- --------------- ----------- ---------------
--------- ----------
3 1 PACKAGE BODY SYS DBMS_PROFILER
05-SEP-99 0 3
2 ANONYMOUS BLOCK <anonymous> <anonymous> 00-DECEMB 0
3
3 PACKAGE BODY SYSTEM DBA_UTILITIES
05-SEP-99 0
4 1 ANONYMOUS BLOCK <anonymous> <anonymous>
00-DECEMB 0
4 2 PACKAGE BODY SYS DBMS_PROFILER
05-SEP-99 0
21 rows
selected.s
SQL> select
runid,unit_number, line#,total_occur, total_time, min_time,
max_time
2 from plsql_profiler_data where runid>2;
RUNID UNIT_NUMBER LINE# TOTAL_OCCUR TOTAL_TIME MIN_TIME MAX_TIME
--------- ----------- --------- ----------- ---------- ---------
---------
3 1 8 12 109762112 3492
98948661
3 1 51 9 50462
2987 9603
3 1 57 2 21893
9097 12795
3 1 60 4 28379
2572 18635
3 1 65 2 12930
5574 7356
3 1 68 4 59095
1961 28399
3 1 73 4 26867
5539 7961
3 1 76 3 14372
1936 10473
3 2 4 1 21613
21613 21613
3 2 5 1 5034924 5034924
5034924
3 2 6 1 41565
41565 41565
3 3 7 1 790506
790506 790506
3 3 15 1 2982
2982 2982
3 3 16 1 25397557 25397557
25397557
3 3 17 1 55236
55236 55236
3 3 18 2 215348
1891 213456
3 3 571 1 284096
284096 284096
3 3 586 1 25581
25581 25581
3 3 587 1 1346
1346 1346
3 3 588 1 1256
1256 1256
3 3 589 1 1251
1251 1251
3 3 590 1 1256
1256 1256
3 3 591 1 1361
1361 1361
3 3 592 1 1256
1256 1256
3 3 593 1 1251
1251 1251
3 3 594 1 1256
1256 1256
3 3 595 1 1256
1256 1256
3 3 596 1 1266
1266 1266
3 3 597 1 1251
1251 1251
3 3 598 1 1456
1456 1456
3 3 599 1 1256
1256 1256
3 3 600 1 1256
1256 1256
3 3 601 1 1256
1256 1256
3 3 602 1 1256
1256 1256
3 3 605 1 2812
2812 2812
3 3 606 1 1566
1566 1566
3 3 610 2 961892
14362 947530
3 3 618 12 1340139 3147
1268453
3 3 630 16 3085227
3112 792383
3 3 638 5 1629234
192128 787013
3 3 647 2 193299
29900 163398
3 3 648 1 8012670 8012670
8012670
3 3 650 1 15901801 15901801
15901801
3 3 656 1 1198859 1198859
1198859
3 3 662 1 9037
9037 9037
3 3 663 1 5299
5299 5299
3 3 664 1 1205895 1205895
1205895
3 3 665 1 285582
285582 285582
3 3 671 1 12210
12210 12210
3 3 672 1 2015673 2015673
2015673
3 3 674 1 1249797 1249797
1249797
3 3 681 1 6695
6695 6695
3 3 682 1 5824
5824 5824
3 3 683 1 351343
351343 351343
3 3 684 1 103763
103763 103763
3 3 690 1 4013
4013 4013
3 3 691 1 3212
3212 3212
3 3 692 1 872691
872691 872691
3 3 693 1 96587
96587 96587
3 3 699 1 3427
3427 3427
3 3 700 1 3007
3007 3007
3 3 701 1 872236
872236 872236
3 3 702 1 96822
96822 96822
3 3 708 1 3698
3698 3698
3 3 709 1 3052
3052 3052
3 3 710 1 890782
890782 890782
3 3 711 1 96702 96702 96702
3 3 717 1 4058
4058 4058
3 3 718 1 3067
3067 3067
3 3 719 1 358239
358239 358239
3 3 720 1 101691
101691 101691
3 3 726 1 4688
4688 4688
3 3 727 1 3252
3252 3252
3 3 728 1 301075
301075 301075
3 3 729 1 95341
95341 95341
3 3 735 1 4163
4163 4163
3 3 736 1 2422
2422 2422
3 3 737 1 314502
314502 314502
3 3 738 1 94695
94695 94695
3 3 744 1 4058
4058 4058
3 3 745 1 2552
2552 2552
3 3 746 1 333633
333633 333633
3 3 747 1 95571
95571 95571
3 3 753 1 27643
27643 27643
3 3 754 1 46664
46664 46664
3 3 755 1 19186
19186 19186
3 3 756 1 9262
9262 9262
3 3 757 1 9147
9147 9147
3 3 758 1 8632
8632 8632
3 3 759 1 2547
2547 2547
3 3 760 1 1078892 1078892
1078892
3 3 761 1 6665
6665 6665
3 3 762 1 1004603 1004603
1004603
3 3 763 1 6980 6980
6980
3 3 764 1 878907
878907 878907
3 3 765 1 6230
6230 6230
3 3 766 1 1086038 1086038
1086038
3 3 767 1 6620
6620 6620
3 3 768 1 811274
811274 811274
3 3 769 1 6215
6215 6215
3 3 770 1 831872
831872 831872
3 3 771 1 5824
5824 5824
3 3 772 1 7541
7541 7541
3 3 773 1 23248826 23248826
23248826
3 3 774 1 19196
19196 19196
3 3 775 1 9543
9543 9543
3 3 776 1 1415167 1415167
1415167
3 3 789 2 49587
4418 45168
3 3 790 1 37226
37226 37226 3 3
795 1 2882 2882 2882
3 3 803 1 3287
3287 3287
3 3 804 1 1725066 1725066
1725066
3 3 806 1 1064539 1064539
1064539
3 3 813 1 8267
8267 8267
3 3 814 1 1262813 1262813
1262813
3 3 816 1 898723
898723 898723
3 3 823 1 7681
7681 7681
3 3 824 1 5664
5664 5664
3 3 825 1 3074648 3074648
3074648
3 3 826 1 105039
105039 105039
3 3 827 1 1244387 1244387
1244387
3 3 835 1 7606
7606 7606
3 3 836 1 8439288 8439288
8439288
3 3 840 1 1069939 1069939
1069939
3 3 848 1 8101
8101 8101
3 3 849 1 4764
4764 4764
3 3 850 1 3050783 3050783
3050783
3 3 851 1 106440
106440 106440
3 3 852 1 1104378 1104378
1104378
3 3 860 1 7276
7276 7276
3 3 861 1 4568
4568 4568
3 3 862 1 3441215 3441215
3441215
3 3 863 1 107231
107231 107231
3 3 864 1 1114997 1114997
1114997
3 3 872 1 7786
7786 7786
3 3 873 1 5094
5094 5094
3 3 874 1 3429094 3429094
3429094
3 3 875 1 107601
107601 107601
3 3 876 1 1080648 1080648
1080648
3 3 884 1 7066
7066 7066
3 3 885 1 4568
4568 4568
3 3 886 1 2179577 2179577
2179577
3 3 887 1 102036
102036 102036
3 3 888 1 937657
937657 937657
3 3 896 1 6720
6720 6720
3 3 897 1 4538
4538 4538
3 3 898 1 2217414 2217414
2217414
3 3 899 1 103187
103187 103187
3 3 900 1 1723660 1723660
1723660
3 3 908 1 8437
8437 8437
3 3 909 1 86055071 86055071
86055071
3 3 912 1 1391037 1391037
1391037
3 3 919 1 9558
9558 9558
3 3 920 1 870328854 870328854
870328854
3 3 922 1 1593429 1593429
1593429
3 3 929 1 10639
10639 10639
3 3 930 1 1148165 1148165
1148165
3 3 932 1 1089516 1089516
1089516
3 3 939 1 4083
4083 4083
3 3 941 5 68741980 272176
67312025
3 3 942 5 32262
4744 10378
3 3 943 4 2935700 414812
1654726
3 3 945 1 6395
6395 6395
3 3 946 1 833808
833808 833808
3 3 949 1 4568
4568 4568
3 3 951 15 82645188 160706
80156282
3 3 952 15 73482
4183 9673
3 3 953 14 7048971 399724
1751063
3 3 955 1 6575
6575 6575
3 3 956 1 471340
471340 471340
3 3 958 1 52539
52539 52539
3 3 959 2 78571
28289 50282
3 3 960 3 139598
7966 86513
4 1 6 1 19146
19146 19146
4 1 7 1 37947
37947 37947
4 2 8 2 116564
4363 112200
4 2 51 2 6675
2987 3688
4 2 60 1 17539
17539 17539
4 2 65 2 14772
5164 9608
4 2 68 1 1941
1941 1941
599 rows
selected.
As you can see, we now have full details about
DBA_UTILITIES. I removed all of the rows that corresponded to
unused sections of code (zero times and executions). The lines
with executions map back into the definitions and code for the
JUST_STATISTICS procedure. Now, by use of the V$SQLTEXT view and
the above data, we should be able to pull the lines that have the
most numbers of executions to see if we can reduce the executions
or time required by reworking the specific lines where performance
is being taxed. For example, in Figure 9 the following lines
should be looked at first:
RUNID
UNIT_NUMBER LINE# TOTAL_OCCUR TOTAL_TIME MIN_TIME MAX_TIME
--------- ----------- --------- ----------- ---------- ---------
--------
3 3 16 1 25397557 25397557
25397557
3 3 650 1
15901801 15901801 15901801
3 3 773 1 23248826 23248826
23248826
3 3 920 1 870328854 870328854
870328854
3 3 941 5 68741980 272176
67312025
3 3 951 15 82645188 160706
80156282
Since the largest problem seems to be with
DBA_UTILITIES.JUST_STATISTICS (runid 3, unit_number 3) in line
number 920, let's pull that line from the SOURCE$ table and take a
quick look at it. Look at Figure 10 to see the results from
selecting line 920.
SQL> desc
source$
Name Null? Type
----------------------------- --------
-------------------------------
OBJ# NOT NULL NUMBER
LINE NOT NULL NUMBER
SOURCE VARCHAR2(4000)
SQL> desc obj$
Name
Null? Type
---------------------------- --------
-------------------------------
OBJ# NOT NULL NUMBER
DATAOBJ# NUMBER
OWNER# NOT NULL NUMBER
NAME NOT NULL VARCHAR2(30)
NAMESPACE NOT NULL NUMBER
SUBNAME VARCHAR2(30)
TYPE# NOT NULL NUMBER
CTIME NOT NULL DATE
MTIME NOT NULL DATE
STIME NOT NULL DATE
STATUS NOT NULL NUMBER
REMOTEOWNER VARCHAR2(30)
LINKNAME VARCHAR2(128)
FLAGS NUMBER
OID$ RAW(16)
SPARE1 NUMBER
SPARE2 NUMBER
SPARE3 NUMBER
SPARE4 VARCHAR2(1000)
SPARE5 VARCHAR2(1000)
SPARE6 DATE
SQL> select obj#,
name, namespace from obj$
2 where name
='DBA_UTILITIES';
OBJ#
NAME NAMESPACE
--------- ------------------------------
---------
3314 DBA_UTILITIES
1 3315
DBA_UTILITIES 2 (Package Body)
SQL> col source
format a60
SQL>select
source from source$ where obj#=3315 and line=920 /
SOURCE
---------------------------------------------------------------
SELECT SUM(BYTES)/1048576 INTO stat_val
SQL> select
line, source from source$ where obj#=3315 and line between 915 and
925
LINE SOURCE
---------
---------------------------------------------------------------------
915 INSERT INTO dba_temp VALUES (stat_name,0,25);
916 COMMIT;
917 END;
918 BEGIN
919 stat_name := 'TOTAL USED MEG';
920 SELECT /* DBA_UTIL.get_bytes */ SUM(BYTES)/1048576
INTO stat_val
921 FROM dba_extents;
922 INSERT INTO dba_temp VALUES (stat_name, stat_val,26);
923 EXCEPTION
924 WHEN NO_DATA_FOUND THEN
925 INSERT INTO dba_temp VALUES (stat_name,0,26);
11 rows
selected.
Notice in Figure 10 that the first select that
just pulled back the single line doesn't tell us much. Once we
broaden the net a bit we can see why that statement is causing the
most time to be used, it is counting the bytes for each and every
used extent in the database! This is just a simple example, I hope
you can see where this type of data could be useful in your PL/SQL
tuning work.
One way to make using DBMS_PROFILER easier, is to
pre-instrument your code via a procedure that you build into all
packages, for an example see Figure 11.
PROCEDURE
profiler_control(
start_stop IN VARCHAR2, run_comm IN VARCHAR2, ret OUT BOOLEAN) AS
ret_code INTEGER;
BEGIN
ret_code:=dbms_profiler.internal_version_check;
IF ret_code !=0 THEN
ret:=FALSE;
ELSIF start_stop NOT IN ('START','STOP') THEN
ret:=FALSE;
ELSIF start_stop = 'START' THEN
ret_code:=DBMS_PROFILER.START_PROFILER(run_comment1=>run_comm);
IF ret_code=0 THEN
ret:=TRUE;
ELSE
ret:=FALSE;
END IF;
ELSIF start_stop = 'STOP' THEN
ret_code:=DBMS_PROFILER.FLUSH_DATA;
ret_code:=DBMS_PROFILER.STOP_PROFILER;
IF ret_code=0 THEN
ret:=TRUE;
ELSE
ret:=FALSE;
END IF;
END IF;
END profiler_control;
By placing the appropriate header entry in the
package header and defining the global variables RUN_PROFILER and
B_RET (both BOOLEAN) you can simple add a couple of lines to the
start and end of each package where performance may become an
issue as shown in Figure 12.
BEGIN
IF RUN_PROFILER THEN
DBA_UTILITIES.PROFILER_CONTROL('START','JUST_STATISTICS',b_ret);
END IF;
?
IF RUN_PROFILER THEN
DBA_UTILITIES.PROFILER_CONTROL('STOP','JUST_STATISTICS',b_ret);
END IF;
END;
The call to stop the profiler should be placed
before any final exception handlers and after any final exception
handlers (in case an exception is generated.)
Once the above procedure and lines of code are
added, you simply switch the package variable RUN_PROFILER to TRUE
to turn on the profiler calls and to FALSE to turn them off. An
example test run is shown in Figure 13.
declare
run_profiler boolean;
BEGIN
dba_utilities.run_profiler:=TRUE;
dba_utilities.running_stats(TRUE);
END;
/
Learn More about Oracle Tuning:
and include the URL for the page.
