PacktLib

Tracing the PL/SQL programs

Code tracing is an important technique to measure the code performance during runtime and identify the expensive areas in the code which can be worked upon to improve the performance. The tracing feature shows the code execution path followed by the server and reveals the time consumed at each step. Often developers assume tracing and debugging as one step, but both are distinctive features. Tracing is a one-time activity which analyses the complete code and prepares the platform for debugging. On the other hand, debugging is the bug identification and fixing activity where the trace report can be used to identify and work upon the problematic points.

Oracle offers multiple methods of tracing:

DBMS_APPLICATION_INFO: The SET_MODULE and SET_ACTION subprograms can be used to register a specific action in a specific module.
DBMS_TRACE: The Oracle built-in package allows tracing of PL/SQL subprograms, exceptions and SQL execution. The trace information is logged into SYS owned tracing tables (created by executing tracetab.sql).
DBMS_SESSION and DBMS_MONITOR: The package can be employed in parallel to set the client ID and monitor the respective client ID. It is equivalent to a 10046 trace and logs the code diagnostics in a trace file.
The trcsess and tkprof utilities: The trcsess utility merges multiple trace files in one and is usually deployed in shared server environments and parallel query sessions. The tkprof utility used to be a conventional tracing utility which generated readable output file. It was useful for large trace files and can also be used to load the trace information into a database.

Besides the methods mentioned in the preceding list, there are third-party tools from LOG4PLSQL and Quest which are used to trace the PL/SQL codes. A typical trace flow in a program is demonstrated in the following diagram:

In this chapter, we will drill down the DBMS_TRACE package to demonstrate the tracing feature in PL/SQL. Further, we will learn the profiling strengths of DBMS_HPROF in PL/SQL.

The DBMS_TRACE package

DBMS_TRACE is a built-in package in Oracle to enable and disable tracing in sessions. As soon as a program is executed in a trace enabled session, the server captures and logs the information in trace log tables. The dbmspbt.sql and prvtpbt.sql table scripts are available in the database installation folder. The trace tables can be analysed to review the execution flow of the PL/SQL program and take decisions in accordance.

Installing DBMS_TRACE

If the DBMS_TRACE package is not installed at the server, it can be installed by running the following scripts from the database installation folder:

$ORACLE_HOME\rdbms\admin\dbmspbt.sql: This script creates the DBMS_TRACE package specification
$ORACLE_HOME\rdbms\admin\prvtpbt.plb: This script creates the DBMS_TRACE package body

The scripts must be executed as the SYS user and in the same order as mentioned.

DBMS_TRACE subprograms

The DBMS_TRACE subprograms deal with the setting of the trace, getting the trace information, and clearing the trace. While configuring the database for the trace, the trace level must be specified to signify the degree of tracing in the session. The trace level majorly deals with two levels. The first level traces all the events of an action while the other level traces only the actions from those program units which have been compiled with the debug and trace option.

The DBMS_TRACE constants are used for setting the trace level. Even the numeric values are available for all the constants, but still the constant names are used in the programs.

The summary of DBMS_TRACE constants is as follows (refer to the Oracle documentation for more details). Note that all constants are of the INTEGER type:

DBMS_TRACE constant	Default	Remarks
`TRACE_ALL_CALLS`	`1`	Traces all calls
`TRACE_ENABLED_CALLS`	`2`	Traces calls which are enabled for tracing
`TRACE_ALL_EXCEPTIONS`	`4`	Traces all exceptions
`TRACE_ENABLED_EXCEPTIONS`	`8`	Traces exceptions which are enabled for tracing
`TRACE_ALL_SQL`	`32`	Traces all SQL statements
`TRACE_ENABLED_SQL`	`64`	Traces SQL statements which are enabled for tracing
`TRACE_ALL_LINES`	`128`	Traces each line
`TRACE_ENABLED_LINES`	`256`	Traces lines which are enabled for tracing
`TRACE_PAUSE`	`4096`	Pauses tracing (controls tracing process)
`TRACE_RESUME`	`8192`	Resume tracing (controls tracing process)
`TRACE_STOP`	`16384`	Stops tracing (controls tracing process)
`TRACE_LIMIT`	`16`	Limits the trace information (controls tracing process)
`TRACE_MINOR_VERSION`	`0`	Administer tracing process
`TRACE_MAJOR_VERSION`	`1`	Administer tracing process
`NO_TRACE_ADMINISTRATIVE`	`32768`	Prevents tracing of administrative events such as: `PL/SQL Trace Tool started` `Trace flags changed` `PL/SQL Virtual Machine started` `PL/SQL Virtual Machine stopped`
`NO_TRACE_HANDLED_EXCEPTIONS`	`65536`	Prevents tracing of handled exceptions

The subprograms contained in the DBMS_TRACE package are as follows:

DBMS_TRACE subprogram	Remarks
`CLEAR_PLSQL_TRACE` procedure	Stops trace data dumping in session
`GET_PLSQL_TRACE_LEVEL` function	Gets the trace level
`GET_PLSQL_TRACE_RUNNUMBER` function	Gets the current sequence of execution of trace
`PLSQL_TRACE_VERSION` procedure	Gets the version number of the trace package
`SET_PLSQL_TRACE` procedure	Starts tracing in the current session
`COMMENT_PLSQL_TRACE` procedure	Includes comment on the PL/SQL tracing
`INTERNAL_VERSION_CHECK` function	Has a value as `0`, if the internal version check has not been done
`LIMIT_PLSQL_TRACE` procedure	Sets limit for the PL/SQL tracing
`PAUSE_PLSQL_TRACE` procedure	Pauses the PL/SQL tracing
`RESUME_PLSQL_TRACE` procedure	Resumes the PL/SQL tracing

In the preceding list, the key subprograms are:

SET_PLSQL_TRACE: It kicks off the PL/SQL tracing session. For example, DBMS_TRACE.SET_PLSQL_TRACE (DBMS_TRACE.TRACE_ALL_SQL) traces all SQL in the program.
CLEAR_PLSQL_TRACE: It stops the tracing session.

PLSQL_TRACE_VERSION returns the current trace version as the OUT parameter value.

Note

Trace level that controls the tracing process (stop, pause, resume, and limit) cannot be used in combination with other trace levels

The PLSQL_DEBUG parameter and the DEBUG option

As a prerequisite, a subprogram can be enabled for tracing only if it is compiled in the debug mode. The PLSQL_DEBUG parameter is used to enable a database, session, or a program for debugging. The compilation parameter can be set at SYSTEM, SESSION, or any specific program level. When set to TRUE, the program units are compiled in the interpreted mode for debug purpose. The Oracle server explicitly compiles the program in interpreted mode to use the strengths of a debugger. However, debugging of a natively compiled program unit is not yet supported in the Oracle database. For this reason, native compilation of program units is less preferable than interpreted mode during development.

ALTER [SYSTEM | SESSION] SET PLSSQL_DEBUG= [TRUE | FALSE]

The trace can be enabled at the subprogram level (not for anonymous blocks):

ALTER [Procedure | Function | Package] [Name]
COMPILE PLSQL_DEBUG= [TRUE | FALSE]
/
Or
ALTER [Procedure | Function | Package] [Name] COMPILE DEBUG [BODY]
/

Enabling tracing at the subprogram level is usually preferred to avoid dumping of huge volume of trace data.

Note

The PLSQL_DEBUG parameter has been devalued in Oracle 11g. When a subprogram is compiled with the PLSQL_DEBUG option set to TRUE in a warning enabled session, the server records the following two warnings:

PLW-06015: parameter PLSQL_DEBUG is deprecated; use PLSQL_OPTIMIZE_LEVEL = 1

PLW-06013: deprecated parameter PLSQL_DEBUG forces PLSQL_OPTIMIZE_LEVEL <= 1

Viewing the PL/SQL trace information

Oracle provides no built-in data dictionary view to query the trace session information. Instead, the trace information is logged into the trace tables. These trace tables can be created by running the $ORACLE_HOME\rdbms\admin\tracetab.sql script as SYS user. The script creates the following two tables:

PLSQL_TRACE_RUNS: This table stores execution-specific information. The following structure shows that the table contains the trace header information such as RUNID and comments:
```
/*Describe the PLSQL_TRACE_RUNS table structure*/
SQL> DESC plsql_trace_runs
Name Null? Type
----------------------------------------- -------- --------------
RUNID NOT NULL NUMBER
RUN_DATE DATE
RUN_OWNER VARCHAR2(31)
RUN_COMMENT VARCHAR2(2047)
RUN_COMMENT1 VARCHAR2(2047)
RUN_END DATE
RUN_FLAGS VARCHAR2(2047)
RELATED_RUN NUMBER
RUN_SYSTEM_INFO VARCHAR2(2047)
SPARE1 VARCHAR2(256)
```
In the preceding table, RUNID is the unique run identifier which derives its value from a sequence, PLSQL_TRACE_RUNNUMBER. The RUN_DATE and RUN_END columns specify the start and end time of the run respectively. The RUN_SYSTEM_INFO and SPARE1 columns are the currently unused columns in the table.

PLSQL_TRACE_EVENTS: This table displays accumulated results from trace executions and captures the detailed trace information:

/*Describe the PLSQL_TRACE_EVENTS table structure*/
SQL> desc plsql_trace_events
Name Null? Type
----------------------------------------- -------- --------------
RUNID NOT NULL NUMBER
EVENT_SEQ NOT NULL NUMBER
EVENT_TIME DATE
RELATED_EVENT NUMBER
EVENT_KIND NUMBER
EVENT_UNIT_DBLINK VARCHAR2(4000)
EVENT_UNIT_OWNER VARCHAR2(31)
EVENT_UNIT VARCHAR2(31)
EVENT_UNIT_KIND VARCHAR2(31)
EVENT_LINE NUMBER
EVENT_PROC_NAME VARCHAR2(31)
STACK_DEPTH NUMBER
PROC_NAME VARCHAR2(31)
PROC_DBLINK VARCHAR2(4000)
PROC_OWNER VARCHAR2(31)
PROC_UNIT VARCHAR2(31)
PROC_UNIT_KIND VARCHAR2(31)
PROC_LINE NUMBER
PROC_PARAMS VARCHAR2(2047)
ICD_INDEX NUMBER
USER_EXCP NUMBER
EXCP NUMBER
EVENT_COMMENT VARCHAR2(2047)
MODULE VARCHAR2(4000)
ACTION VARCHAR2(4000)
CLIENT_INFO VARCHAR2(4000)
CLIENT_ID VARCHAR2(4000)
ECID_ID VARCHAR2(4000)
ECID_SEQ NUMBER
CALLSTACK CLOB
ERRORSTACK CLOB

The following points can be noted about this table:

The RUNID column references the RUNID column of the PLSQL_TRACE_RUNS table
EVENT_SEQ is the unique event identifier within a single run
The EVENT_UNIT, EVEN_UNIT_KIND, EVENT_UNIT_OWNER, and EVENT_LINE columns capture the program unit information (such as name, type, owner, and line number) which initiates the trace event
The PROC_NAME, PROC_UNIT, PROC_UNIT_KIND, PROC_OWNER, and PROC_LINE columns capture the procedure information (such as name, type, owner, and line number) which is currently being traced
The EXCP and USER_EXCP columns apply to the exceptions occurring during the trace
The EVENT_COMMENT column gives user defined comment or the actual event description
The MODULE, ACTION, CLIENT_INFO, CLIENT_ID, ECID_ID, and ECID_SEQ columns capture information about the session running on a SQL*Plus client
The CALLSTACK and ERRORSTACK columns store the call stack information

Once the script has been executed, the DBA should create public synonyms for the tables and sequence in order to be accessed by all users.

/*Connect as SYSDBA*/
Conn sys/system as SYSDBA
Connected.
/*Create synonym for PLSQL_TRACE_RUNS*/
CREATE PUBLIC SYNONYM plsql_trace_runs FOR plsql_trace_runs
/
Synonym created.
/*Create synonym for PLSQL_TRACE_EVENTS*/
CREATE PUBLIC SYNONYM plsql_trace_events FOR plsql_trace_events
/
Synonym created.
/*Create synonym for PLSQL_TRACE_RUNNUMBER sequence*/
CREATE PUBLIC SYNONYM plsql_trace_runnumber FOR plsql_trace_runnumber
/
Synonym created.
/*Grant privileges on the PLSQL_TRACE_RUNS*/
GRANT select, insert, update, delete ON plsql_trace_runs TO PUBLIC
/
Grant succeeded.
/*Grant privileges on the PLSQL_TRACE_EVENTS*/
GRANT select, insert, update, delete ON plsql_trace_events TO PUBLIC
/
Grant succeeded.
/*Grant privileges on the PLSQL_TRACE_RUNNUMBER*/
GRANT select ON plsql_trace_runnumber TO PUBLIC
/
Grant succeeded.

Demonstrating the PL/SQL tracing

PL/SQL tracing is demonstrated in the following steps:

1. The F_GET_LOC function looks as follows (this function has been already created in the schema):

/*Connect as ORADEV user*/
Conn ORADEV/ORADEV
Connected.
/*Create the function*/
CREATE OR REPLACE FUNCTION F_GET_LOC (P_EMPNO NUMBER)
RETURN VARCHAR2
IS
/*Cursor select location for the given employee*/
CURSOR C_DEPT IS
SELECT d.loc
FROM employees e, departments d
WHERE e.deptno = d.deptno
AND e.empno = P_EMPNO;
l_loc VARCHAR2(100);
BEGIN
/*Cursor is open and fetched into a local variable*/
OPEN C_DEPT;
FETCH C_DEPT INTO l_loc;
CLOSE C_DEPT;
/*Location returned*/
RETURN l_loc;
END;
/
Function created.

We will trace the execution path for the preceding function.

2. Recompile the F_GET_LOC function for tracing:

/*Compile the function in debug mode*/
SQL> ALTER FUNCTION F_GET_LOC COMPILE DEBUG
/
Function altered.

3. Start the tracing session to trace all calls:
```
BEGIN
/*Enable tracing for all calls in the session*/
DBMS_TRACE.SET_PLSQL_TRACE(DBMS_TRACE.TRACE_ALL_CALLS);
END;
/
```
Note
Specify additional trace levels using the + sign as:
DBMS_TRACE.SET_PLSQL_TRACE (tracelevel1 + tracelevel2 ...)

4. Execute the function and capture the result into a bind variable:

/*Declare a SQLPLUS environment variable*/
SQL> VARIABLE M_LOC VARCHAR2(100);
/*Execute the function and assign the return output to the variable*/
SQL> EXEC :M_LOC := F_GET_LOC (7369);
PL/SQL procedure successfully completed.
/*Print the variable*/
SQL> PRINT M_LOC
M_LOC
-----------------------------------------
DALLAS

5. Stop the trace session:

BEGIN
/*Stop the trace session*/
DBMS_TRACE.CLEAR_PLSQL_TRACE;
END;
/

6. Query the trace log tables.
Query the PLSQL_TRACE_RUNS table to retrieve the current RUNID:
```
/*Query the PLSQL_TRACE_RUNS table*/
SELECT runid, run_owner, run_date
FROM plsql_trace_runs
ORDER BY runid
/
RUNID RUN_OWNER RUN_DATE
---------- ------------------------------- ---------
1 ORADEV 29-JAN-12
```
Query the PLSQL_TRACE_EVENTS table to retrieve the trace events for the RUNID as 1.
The highlighted portion shows the tracing of execution of the F_GET_LOC function. The trace events appearing before and after the highlighted portion represent the starting and stopping of the trace session.
```
/*Query the PLSQL_TRACE_EVENTS table*/
SELECT runid,
event_comment,
event_unit_owner,
event_unit,
event_unit_kind,
event_line
FROM plsql_trace_events
WHERE runid = 1
ORDER BY event_seq
/
```
The output of the preceding query is shown in the following screenshot:
The query output shows the F_GET_LOC function execution flow starting from the time the trace session started (EVENT_COMMENT = PL/SQL Trace Tool started) till the trace session was stopped (EVENT_COMMENT = PL/SQL trace stopped).