03 December 2011

Hacking Oracle Supplied Packages With PL/SQL Hierarchical Profiler :)


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;


No comments: