I am joking J
I am not going to tell you how to hack
DBMS_* packages. The answer is easy and simple; I do not knowJ.What I will tell you now is yet another powerful tool of Oracle database,
PL/SQL Hierarchical Profiler. By the help of this Profiler, you can infer code
execution paths that are –somehow- internal of Oracle’s supplied packages and
gather statistical information for PL/SQL programs. This tool consist of 3 tables
(DBMSHP_*), one PL/SQL package (DBMS_HPROF) and one executable (plshprof). In
order to create these tables, dbmshptab.sql file in the
$ORACLE_HOME/rdbms/admin should be run. That is it. Now you can take
statistical information about PL/SQL blocks.
Oracle has many other performance analyzing
tools/packages/helpers, like DBMS_PROFILE, DBMS_TRACE, tkprof, StatsPack, AWR
and so on. Regarding to your Oracle version, you can use one of these tools to
find out bottleneck points inside your SQL and/or PL/SQL codes. DBMS_HPROF
gathers some profiling information between its START_PROFILING and STOP_PROFILING
procedures. Profiling data is written in a file which should be specified in START_PROFILING
procedure. The file contains lots of informational data that is hard to understand
and analyze. A small piece of this file is shown below:
P#V
PLSHPROF Internal Version 1.0
P#!
PL/SQL Timer Started
P#C
SQL."MENNAN"."GENERATEHPROFREPORT"::7."__dyn_sql_exec_line20"
#20
P#X
75
P#C
PLSQL."".""."__plsql_vm"
P#X
2
P#C
PLSQL."".""."__anonymous_block"
P#X
22
P#C
SQL."".""."__static_sql_exec_line7" #7
P#X
153
P#C
PLSQL."".""."__plsql_vm"
P#R
P#X
4
…
…
P#X
1
P#R
P#X
55
P#R
P#C
PLSQL."SYS"."DBMS_HPROF"::11."STOP_PROFILING"#980980e97e42f8ec
#59
P#R
P#!
PL/SQL Timer Stopped
In order to store this profiling
information into some relational tables, ANALYZE procedure should be run.
As its name shows, profiling data is analyzing in terms of clicks and execution
times. A kind of hierarchical relation between caller and called programs are
also inserted in the HPROF tables. These tables (and their contents for a
sample run) are shown below:
SELECT * FROM
DBMSHP_RUNS;
|
RUNID
|
RUN_TIMESTAMP
|
TOTAL_ELAPSED_TIME
|
RUN_COMMENT
|
|
39
|
28/11/2011
19:46:53,244985
|
140651
|
|
SELECT * FROM
DBMSHP_FUNCTION_INFO;
|
RUNID
|
SYMBOLID
|
OWNER
|
MODULE
|
TYPE
|
FUNCTION
|
LINE#
|
HASH
|
NAME
SPACE
|
SUBTREE_
ELAPSED_ TIME
|
FUNCTION_
ELAPSED_ TIME
|
CALLS
|
|
39
|
1
|
|
|
|
__anonymous_block
|
0
|
|
PLSQL
|
1398
|
299
|
4
|
|
39
|
2
|
|
|
|
__anonymous_block@1
|
0
|
|
PLSQL
|
60
|
60
|
2
|
|
39
|
3
|
|
|
|
__plsql_vm
|
0
|
|
PLSQL
|
1444
|
46
|
4
|
|
39
|
4
|
|
|
|
__plsql_vm@1
|
0
|
|
PLSQL
|
69
|
9
|
2
|
|
39
|
5
|
EXFSYS
|
DBMS_EXPFIL
|
PACKAGE
BODY
|
CREATE_ATTRIBUTE_SET
|
26
|
….
|
PLSQL
|
140616
|
204
|
1
|
|
39
|
6
|
EXFSYS
|
DBMS_EXPFIL_DR
|
PACKAGE
BODY
|
ATTRSET_EXISTS
|
134
|
….
|
PLSQL
|
216
|
44
|
1
|
|
39
|
7
|
EXFSYS
|
DBMS_EXPFIL_DR
|
PACKAGE
BODY
|
CREATE_ATTRIBUTE_SET
|
202
|
….
|
PLSQL
|
8865
|
113
|
1
|
|
39
|
8
|
EXFSYS
|
DBMS_EXPFIL_IR
|
PACKAGE
BODY
|
GET_OBJECT_OWNER_N_NAME
|
7
|
|
PLSQL
|
1050
|
48
|
1
|
|
39
|
9
|
EXFSYS
|
DBMS_EXPFIL_IR
|
PACKAGE
BODY
|
TRANSFORM_SUBEXP
|
160
|
|
PLSQL
|
860
|
26
|
1
|
|
39
|
10
|
EXFSYS
|
DBMS_RLMGR
|
PACKAGE
BODY
|
CREATE_EVENT_STRUCT
|
1431
|
|
PLSQL
|
140651
|
35
|
1
|
|
39
|
11
|
EXFSYS
|
EXF$CURRUSER
|
FUNCTION
|
EXF$CURRUSER
|
1
|
|
PLSQL
|
212
|
55
|
1
|
|
39
|
12
|
EXFSYS
|
TRANSFORM_LHS
|
FUNCTION
|
TRANSFORM_LHS
|
1
|
|
PLSQL
|
834
|
834
|
1
|
|
39
|
13
|
SYS
|
DBMS_ASSERT
|
PACKAGE
BODY
|
SIMPLE_SQL_NAME
|
153
|
|
PLSQL
|
216
|
216
|
3
|
|
39
|
14
|
SYS
|
DBMS_HPROF
|
PACKAGE
BODY
|
STOP_PROFILING
|
59
|
|
PLSQL
|
0
|
0
|
1
|
|
39
|
15
|
|
|
|
__dyn_sql_exec_line19
|
19
|
|
SQL
|
665
|
628
|
1
|
|
39
|
16
|
|
|
|
__dyn_sql_exec_line20
|
20
|
|
SQL
|
294
|
262
|
1
|
|
39
|
17
|
|
|
|
__static_sql_exec_line18
|
18
|
|
SQL
|
140
|
140
|
1
|
|
39
|
18
|
EXFSYS
|
DBMS_EXPFIL
|
PACKAGE
BODY
|
__dyn_sql_exec_line175
|
175
|
|
SQL
|
129857
|
128413
|
1
|
|
39
|
19
|
EXFSYS
|
DBMS_EXPFIL
|
PACKAGE
BODY
|
__static_sql_exec_line216
|
216
|
|
SQL
|
47
|
47
|
1
|
|
39
|
20
|
EXFSYS
|
DBMS_EXPFIL
|
PACKAGE
BODY
|
__static_sql_exec_line42
|
42
|
|
SQL
|
91
|
91
|
1
|
|
39
|
21
|
EXFSYS
|
DBMS_EXPFIL_DR
|
PACKAGE
BODY
|
__static_sql_exec_line139
|
139
|
|
SQL
|
172
|
172
|
1
|
|
39
|
22
|
EXFSYS
|
DBMS_EXPFIL_DR
|
PACKAGE
BODY
|
__static_sql_exec_line217
|
217
|
|
SQL
|
8410
|
8410
|
1
|
|
39
|
23
|
EXFSYS
|
DBMS_EXPFIL_DR
|
PACKAGE
BODY
|
__static_sql_exec_line228
|
228
|
|
SQL
|
192
|
192
|
1
|
|
39
|
24
|
EXFSYS
|
DBMS_EXPFIL_DR
|
PACKAGE
BODY
|
__static_sql_exec_line260
|
260
|
|
SQL
|
150
|
150
|
1
|
|
39
|
25
|
EXFSYS
|
EXF$CURRUSER
|
FUNCTION
|
__static_sql_exec_line8
|
8
|
|
SQL
|
157
|
157
|
1
|
SELECT * FROM DBMSHP_PARENT_CHILD_INFO;
|
RUNID
|
PARENTSYMID
|
CHILDSYMID
|
SUBTREE_ELAPSED_TIME
|
FUNCTION_ELAPSED_TIME
|
CALLS
|
|
39
|
1
|
15
|
665
|
628
|
1
|
|
39
|
1
|
16
|
294
|
262
|
1
|
|
39
|
1
|
17
|
140
|
140
|
1
|
|
39
|
3
|
1
|
1398
|
299
|
4
|
|
39
|
4
|
2
|
60
|
60
|
2
|
|
39
|
5
|
18
|
129857
|
128413
|
1
|
|
39
|
5
|
7
|
8865
|
113
|
1
|
|
39
|
5
|
8
|
1050
|
48
|
1
|
|
39
|
5
|
6
|
216
|
44
|
1
|
|
39
|
5
|
11
|
212
|
55
|
1
|
|
39
|
5
|
20
|
91
|
91
|
1
|
|
39
|
5
|
13
|
74
|
74
|
1
|
|
39
|
5
|
19
|
47
|
47
|
1
|
|
39
|
6
|
21
|
172
|
172
|
1
|
|
39
|
7
|
22
|
8410
|
8410
|
1
|
|
39
|
7
|
23
|
192
|
192
|
1
|
|
39
|
7
|
24
|
150
|
150
|
1
|
|
39
|
8
|
9
|
860
|
26
|
1
|
|
39
|
8
|
13
|
142
|
142
|
2
|
|
39
|
9
|
12
|
834
|
834
|
1
|
|
39
|
10
|
5
|
140616
|
204
|
1
|
|
39
|
11
|
25
|
157
|
157
|
1
|
|
39
|
15
|
4
|
37
|
4
|
1
|
|
39
|
16
|
4
|
32
|
5
|
1
|
|
39
|
18
|
3
|
1444
|
46
|
4
|
If
you want to see all reports in a more human readable form, In HTML form, you
can run plshprof executable. By the help of this small and nice program, a
number of HTML files are creating by reading profiling data. A sample of main page
of this output file is shown below:
PL/SQL
Elapsed Time (microsecs) Analysis
140651 microsecs (elapsed
time) & 35 function calls
The PL/SQL Hierarchical
Profiler produces a collection of reports that present information derived from
the profiler's output log in a variety of formats. The following reports have
been found to be the most generally useful as starting points for browsing:
·
Function Elapsed Time (microsecs) Data sorted
by Total Subtree Elapsed Time (microsecs)
·
Function Elapsed Time (microsecs) Data sorted
by Total Function Elapsed Time (microsecs)
In addition, the following
reports are also available:
·
Function Elapsed Time (microsecs) Data sorted
by Function Name
·
Function Elapsed Time (microsecs) Data sorted
by Total Descendants Elapsed Time (microsecs)
·
Function Elapsed Time (microsecs) Data sorted
by Total Function Call Count
·
Function Elapsed Time (microsecs) Data sorted
by Mean Subtree Elapsed Time (microsecs)
·
Function Elapsed Time (microsecs) Data sorted
by Mean Function Elapsed Time (microsecs)
·
Function Elapsed Time (microsecs) Data sorted
by Mean Descendants Elapsed Time (microsecs)
·
Module Elapsed Time (microsecs) Data sorted by
Total Function Elapsed Time (microsecs)
·
Module Elapsed Time (microsecs) Data sorted by
Module Name
·
Module Elapsed Time (microsecs) Data sorted by
Total Function Call Count
·
Namespace Elapsed Time (microsecs) Data sorted
by Total Function Elapsed Time (microsecs)
·
Namespace Elapsed Time (microsecs) Data sorted
by Namespace
·
Namespace Elapsed Time (microsecs) Data sorted
by Total Function Call Count
·
Parents and Children Elapsed Time (microsecs)
Data
Up to now, I have showed how to use this
tool in order to analyze PL/SQL blocks.
Now I will tell you how to understand the structure of
existing/unknown/wrapped PL/SQL source codes like packages. Suppose that you
want to know what Oracle does when you run “dbms_rlmgr.create_event_struct”
procedure. The package is wrapped and you cannot see private functions inside dbms_rlmgr package. I will use DBMS_HPROF to investigate the create_event_struct procedure. I have written a pretty function to analyze a PL/SQL
block. You can check the content of code at the end of this post. This code
simply takes a PL/SQL block and executes it dynamically with adding profiling
data. Then HFPROF analyze is done, at the end plshprof is executed to get
complete html files. When I run this code for “dbms_rlmgr.create_event_struct”,
following output is created:
DECLARE
vs_PLSQLBlock
VARCHAR2(32000);
BEGIN
--dbms_rlmgr.drop_event_struct(event_struct
=> 'TEST3');
vs_PLSQLBlock := '
BEGIN
dbms_rlmgr.create_event_struct( ''TEST3'' );
END;
';
GenerateHProfReport(vs_PLSQLBlock, 'dbms_rlmgr_test3');
END;
/
Input PLSQL
Block
========================================================
BEGIN
dbms_rlmgr.create_event_struct( 'TEST3' );
END;
========================================================
HProfDirectoryName = MT_TEMP
HProfFileName = dbms_rlmgr_test3.txt
HProfileRunId = 45
OracleHomePath =
/home/oracle/app/oracle/product/11.2.0/dbhome_2
HProfDirectoryPath
= /home/oracle/temp_dir
CommandText =
/bin/mkdir /home/oracle/temp_dir/dbms_rlmgr_test3
Return of
command =
CommandText =
/home/oracle/app/oracle/product/11.2.0/dbhome_2/bin/plshprof -output
/home/oracle/temp_dir/dbms_rlmgr_test3/pd
/home/oracle/temp_dir/dbms_rlmgr_test3.txt
Return of
command = PLSHPROF: Oracle Database 11g
Enterprise Edition Release 11.2.0.2.0 - Production
[28 symbols
processed]
[Report written
to '/home/oracle/temp_dir/dbms_rlmgr_test3/pd.html']
CommandText =
/bin/mv
/home/oracle/temp_dir/dbms_rlmgr_test3.txt
/home/oracle/temp_dir/dbms_rlmgr_test3
Return of
command =
CommandText =
/bin/ls
/home/oracle/temp_dir/dbms_rlmgr_test3
Return of
command = dbms_rlmgr_test3.txt
pd_2c.html
pd_2f.html
pd_2n.html
pd_fn.html
pd.html
pd_md.html
pd_mf.html
pd_ms.html
pd_nsc.html
pd_nsf.html
pd_nsp.html
pd_pc.html
pd_tc.html
pd_td.html
pd_tf.html
pd_ts.html
OK, everything has run successfully. Some
html files are created on the file system. HFPROF* tables store related data.
It is now possible to analyze…
Called-caller modules in parent-child
structure are shown below.
dbms_rlmgr.create_event_struct(event_struct
=> 'TEST3' );
==================================================================
[10] DBMS_RLMGR.CREATE_EVENT_STRUCT(PACKAGE BODY)
[5]
DBMS_EXPFIL.CREATE_ATTRIBUTE_SET(PACKAGE BODY)
[18] DBMS_EXPFIL.__dyn_sql_exec_line175(PACKAGE BODY)
[3]
.__plsql_vm()--4calls
[1]
.__anonymous_block() --4calls
[15]
.__dyn_sql_exec_line19()
[4]
.__plsql_vm@1()
[2]
.__anonymous_block@1()--2calls
[16]
.__dyn_sql_exec_line20()
[4]
.__plsql_vm@1()
[17]
.__static_sql_exec_line18()
[7]
DBMS_EXPFIL_DR.CREATE_ATTRIBUTE_SET(PACKAGE BODY)
[22]
DBMS_EXPFIL_DR.__static_sql_exec_line217(PACKAGE BODY)
[23]
DBMS_EXPFIL_DR.__static_sql_exec_line228(PACKAGE BODY)
[24]
DBMS_EXPFIL_DR.__static_sql_exec_line260(PACKAGE BODY)
[8]
DBMS_EXPFIL_IR.GET_OBJECT_OWNER_N_NAME(PACKAGE BODY)
[9]
DBMS_EXPFIL_IR.TRANSFORM_SUBEXP(PACKAGE BODY)
[12]
TRANSFORM_LHS(FUNCTION)
[13]
DBMS_ASSERT.SIMPLE_SQL_NAME(PACKAGE BODY)--2calls
[6]
DBMS_EXPFIL_DR.ATTRSET_EXISTS(PACKAGE BODY)
[21]
DBMS_EXPFIL_DR.__static_sql_exec_line139(PACKAGE BODY)
[11] EXF$CURRUSER(FUNCTION)
[25]
__static_sql_exec_line8(FUNCTION)
[20] DBMS_EXPFIL.__static_sql_exec_line42(PACKAGE BODY)
[13] DBMS_ASSERT.SIMPLE_SQL_NAME(PACKAGE BODY)
[19]
DBMS_EXPFIL.__static_sql_exec_line216(PACKAGE BODY)
This part is important. As you see, first
module with id of 10 which is our first line of code that creates an event
structure (CREATE_EVENT_STRUCT) is called within DBMS_RLMGR package body. This procedure internally calls (or jumps) DBMS_EXPFIL.CREATE_ATTRIBUTE_SET procedure. This procedure also calls the modules (or functions)
with ids of 3, 1, 15, 4 and 2 respectively. CREATE_EVENT_STRUCT also calls
some other procedures which are not visible, private. For instance DBMS_ASSERT.SIMPLE_SQL_NAME is called within DBMS_EXPFIL_IR.GET_OBJECT_OWNER_N_NAME procedure. With this way, you can infer the executing path of unknown
procedures. Another example is when you execute PUT_LINE in the DBMS_OUTPUT package, Oracle
calls PUT and NEWLINE procedures (You can find this by using this profiler method).
Somehow, Oracle made a refactoring for PUT_LINE procedure,
which I expected. You can infer more useful Oracle’s internal information
regarding to code executions from the profiling data.
Hierarchical Profiler is a really good
analyzing tool for PL/SQL application developers. I can recommend every
developer to use such these tools to analyze their software and find out
bottleneck points before production. Thanks Oracle to supply these cool tools
for usJ
Procedure that I used is shown below.
For other functions like GetEnvValueViaC ,
please check this
post…
CREATE OR REPLACE PROCEDURE GenerateHProfReport( pis_PLSQLBlock IN VARCHAR2, pis_Description IN VARCHAR2,
pis_DirectoryName IN VARCHAR2 DEFAULT 'MT_TEMP')
AUTHID CURRENT_USER
IS
vs_HProfDirectoryName VARCHAR2(32);
vs_HProfFileName VARCHAR2(32);
vn_HProfileRunId NUMBER;
vs_HProfDirectoryPath VARCHAR2(64);
vs_CommandText VARCHAR2(4000);
vs_ReturnText VARCHAR2(4000);
vs_OracleHomePath VARCHAR2(64);
vs_HProfFileNameExt VARCHAR2(8);
BEGIN
vs_HProfFileNameExt := '.txt';
vs_HProfDirectoryName := pis_DirectoryName;
vs_HProfFileName := pis_Description ||
vs_HProfFileNameExt;
dbms_output.put_line( 'pis_PLSQLBlock' || pis_PLSQLBlock);
--disable
output for unnecessary symbols in profiler report
dbms_output.disable;
--start
profiling....
DBMS_HPROF.START_PROFILING(vs_HProfDirectoryName, vs_HProfFileName);
--this
is line 20. After this line, code to be analyzed should be placed
EXECUTE IMMEDIATE
pis_PLSQLBlock;
--end
of code...
--it
is enough to profile
DBMS_HPROF.STOP_PROFILING();
--
analyze; that is it.
vn_HProfileRunId :=
DBMS_HPROF.ANALYZE(vs_HProfDirectoryName, vs_HProfFileName);
dbms_output.enable;
dbms_output.put_line('HProfDirectoryName
= ' || vs_HProfDirectoryName);
dbms_output.put_line('HProfFileName
= ' || vs_HProfFileName);
dbms_output.put_line('vn_HProfileRunId
= ' || vn_HProfileRunId);
--rest
of code is related with plshprof executable.
--if
you do not need HTML reports, please skip following steps
--profiler
data exists in DBMSHP_* tables.
vs_OracleHomePath := GetEnvValueViaC('ORACLE_HOME');
dbms_output.put_line( 'vs_OracleHomePath = ' || vs_OracleHomePath );
SELECT t.DIRECTORY_PATH INTO vs_HProfDirectoryPath FROM
ALL_DIRECTORIES t WHERE t.DIRECTORY_NAME =
vs_HProfDirectoryName;
dbms_output.put_line( 'vs_HProfDirectoryPath = ' || vs_HProfDirectoryPath );
--create
a directory for plshprof report
vs_CommandText := '/bin/mkdir ' || vs_HProfDirectoryPath || '/' || pis_Description ;
dbms_output.put_line( 'vs_CommandText = ' || vs_CommandText );
vs_ReturnText
:= ExecuteShellCommandViaC(vs_CommandText);
dbms_output.put_line('Return of = ' || vs_ReturnText);
--run
plshprof executable to create more readable HTML report.Usage : plshprof
-output <report_file_path> <profiler_data_file>
vs_CommandText := vs_OracleHomePath || '/bin/plshprof -output ' || vs_HProfDirectoryPath || '/' || pis_Description || '/pd ' ||
vs_HProfDirectoryPath || '/' || vs_HProfFileName;
dbms_output.put_line( 'vs_CommandText = ' || vs_CommandText );
vs_ReturnText
:= ExecuteShellCommandViaC(vs_CommandText);
dbms_output.put_line('Return of = ' || vs_ReturnText);
--move
profiler data file to the HTML report directory
vs_CommandText := '/bin/mv ' || vs_HProfDirectoryPath || '/' || vs_HProfFileName
|| ' ' || vs_HProfDirectoryPath || '/' ||
pis_Description ;
dbms_output.put_line( 'vs_CommandText = ' || vs_CommandText );
vs_ReturnText
:= ExecuteShellCommandViaC(vs_CommandText);
dbms_output.put_line('Return of = ' || vs_ReturnText);
END GenerateHProfReport;
CREATE OR REPLACE FUNCTION GetHProfFunctionInfo
(
pin_RunId
IN NUMBER,
pin_SymbolId IN NUMBER
) RETURN VARCHAR2 IS
vs_HProfFunctionInfo varchar2(100);
BEGIN
SELECT '[' ||
SYMBOLID || '] ' || OWNER || '.' || decode(TYPE, 'FUNCTION', '', 'PROCEDURE', '', module || '.' )
|| FUNCTION || '(' || TYPE || ')'
INTO vs_HProfFunctionInfo
FROM DBMSHP_FUNCTION_INFO
WHERE RUNID = pin_RunId
AND SYMBOLID = pin_SymbolId;
RETURN vs_HProfFunctionInfo;
EXCEPTION
WHEN OTHERS THEN
RETURN NULL;
END GetHProfFunctionInfo;
