Oracle 8i's Profiler analyzes PL/SQL code and locates bottlenecks. As you probably know, the first working version of your code is usually inefficient and slow. There is a way to measure its execution time on a line-by-line basis without using a profiler, but it's tedious and slow. It involves calling the GET_TIME function (from the Oracle-supplied DBMS_UTILITY package) before and after selected lines of code. That's primitive and inefficient because it requires adding multiple lines of temporary code and recompiling it. Plus you still don't know how many times each line gets executed without adding even more code.
The Problem
Because PL/SQL programming involves writing and using custom and Oracle-supplied
packages, as well as standalone procedures and functions, performance tuning
is an important task for Oracle developers. Checking code line by line
is slow and inefficient because it requires adding multiple lines of temporary
code and recompiling it.
Solution
Use the Oracle 8i Profiler to analyze PL/SQL code and locate bottlenecks.
Improving PL/SQL code performance is an iterative process:
1.Run the application code with profiler data collection
enabled.
2.Analyze the profiler data and identify performance
problems.
3.Fix the problems.
Using the DBMS_PROFILER Package
The Profiler API is implemented as a PL/SQL package, called DBMS_PROFILER.
This package provides services for collecting statistics related to the
execution of PL/SQL code and persistently storing it in three profiler
tables (PLSQL_PROFILER_DATA, PLSQL_PROFILER_RUNS, and PLSQL_PROFILER_UNITS)
in order to analyze the code and identify performance problems.
The DBMS_PROFILER package is not created by default by the database.
It must be generated by the ProfLoad.sql script. This script is supplied
with Oracle 8.1.6 and is located in the $ORACLE_HOME/Rdbms/Admin directory.
(It's not provided in version 8.1.5 but can be downloaded from technet.oracle.com.
OTN registration is required.) This script has to be executed by a SYS
or INTERNAL user, and access has to be granted to PUBLIC. This script calls
two other scripts, Dbmspbp.sql and Prvtpbp.plb, located in the same directory.
A typical profiling session consists of the following steps:
Start the profiler data collection.
Execute the PL/SQL code.
Stop the profiler data collection.
The Oracle 8i profiler gathers information at the PL/SQL virtual machine
level, which includes the total number of times each line has been executed,
the total amount of time that has been spent executing that line, and the
minimum and maximum times that have been spent on a particular execution
of that line.
Creating the Test Data and Stored Procedure
Listing 1 shows the necessary code for creating the table and stored
procedure, which I use in this article's examples. Let's create the TestData
table and TestProc stored procedure to use in our profiling sessions.
Listing 1. Code for the TestData Table and TestProc Stored Procedure.
The red line is line 18, which is analyzed in Figure 2 and compared to
line 16 in Listing 2.
DROP TABLE TestData CASCADE CONSTRAINTS;
CREATE TABLE TestData(
TestData_ID NUMBER(10) NOT NULL,
Name VARCHAR2 (30),
CONSTRAINT TestData_PK PRIMARY KEY (TestData_ID));
CREATE OR REPLACE PROCEDURE TestProc(
p_Count NUMBER) IS
TYPE t_Numbers IS TABLE OF NUMBER
INDEX BY BINARY_INTEGER;
v_Nums t_Numbers;
BEGIN
FOR n_Count IN 1..p_Count
LOOP
v_Nums(n_Count)
:= n_Count;
END LOOP;
FOR n_Count IN 1..p_Count
LOOP
INSERT INTO
TestData (TestData_ID, Name)
VALUES ( v_Nums(n_Count),
'Profiler Test ' || TO_CHAR(v_Nums(n_Count)));
END LOOP;
COMMIT;
DBMS_OUTPUT.PUT_LINE('Procedure TestProc: ' || TO_CHAR(p_Count)
|| ' rows created in TestData table.');
EXCEPTION
WHEN OTHERS THEN
ROLLBACK;
END TestProc;
/
Profiling with TOAD
I'm using TOAD (Tool for Oracle Application Developers) version 6.5.0.0
from Quest Software, Inc., to profile this TestProc stored procedure. Oracle
doesn't have a graphic profiling tool of its own. You can download a free
trial version of TOAD from the Quest Web site.
To use the profiler in TOAD:
1 - Start TOAD and select Database > PL/SQL Profiling to turn on the profiler, or click the Toggle PL/SQL Profiling button in the main TOAD toolbar. The icon for the button is a stopwatch.
2 - Execute the procedure TestProc from the Schema Browser or the Procedure
Editor using the Execute (lightning bolt) button. You will be prompted
to enter a value for the p_Count IN parameter (10000) and a description
of the procedure being executed ("TOAD, TestProc Run 1 - 12/19/2000").
This will show up in the Profile Analysis window when you analyze the results.
You could run the procedure several times to get some data into the profiling
tables.
Make sure you truncate the TestData table before each run by issuing
the following SQL command:
TRUNCATE TABLE TestData;
Turn off profiling if you want at this point.
3 - Select Database > Profiler Analysis to bring up the Profiler Analysis window. There are three levels to the data. The top level represents the individual "Runs" of each procedure executed while profiling was enabled (see Figure 1 (The TOAD profiler analysis window shows three runs of the original procedure). )
4 - Double-click on one item to see the execution stats for that individual run. At this level, you can double-click to see the line-by-line performance times for individual procedures called during the profiling (see Figure 2 Line-by-line analysis of TestProc original version, run 3. As you can see, line 18 took 99.61% of the total time to execute (10,000 passes, 5,852 ms. total). )
The Code column, where you are supposed to see actual PL/SQL code lines, was actually empty after the run completed. I had to create my own stored procedure, ProfilerLoadSource, and run it to fix this problem by populating the Code column with lines of source code. According to the Quest Software support, it works fine there; they could not reproduce the problem.
Let's improve this code by utilizing the FORALL statement that Oracle 8i introduced to support bulk binds
Replace the keyword FOR with FORALL and remove the LOOP and END LOOP statements, which are no longer needed because all 10,000 inserts will be passed to the SQL engine in one step. Listing 2 shows the improved version of TestProc.
Listing 2. An improved version of the TestProc stored procedure. The
red line is line 16, which is analyzed in Figure 4 and compared to line
18 in Listing 1.
CREATE OR REPLACE PROCEDURE TestProc(
p_Count NUMBER) IS
TYPE t_Numbers IS TABLE OF NUMBER INDEX BY BINARY_INTEGER;
v_Nums t_Numbers;
BEGIN
FOR n_Count IN 1..p_Count
LOOP
v_Nums(n_Count)
:= n_Count;
END LOOP;
FORALL n_Count IN 1..p_Count
INSERT INTO TestData (TestData_ID,
Name)
VALUES ( v_Nums(n_Count),
'Profiler Test ' || TO_CHAR(v_Nums(n_Count)));
COMMIT;
DBMS_OUTPUT.PUT_LINE('Procedure TestProc: ' || TO_CHAR(p_Count)
|| ' rows created in TestData table.');
EXCEPTION
WHEN OTHERS THEN
ROLLBACK;
END TestProc;
/
Let's use TOAD to profile an improved version of the TestProc stored procedure. Figure 3 (An improved version of the TestProc stored procedure, runs 4–6. ) shows the results of the next three runs. As you can see, the improved TestProc executes 10 to 12 times faster (average time 0.56 sec.) than the original one (average time 5.99 sec.).
As Figure 4 A line-by-line analysis
of the improved TestProc, run 6. Line 16 was executed only once instead
of 10,000 times and it took only 584 ms. instead of 5,852 ms., as line
18 did in the original TestProc line-by-line analysis.) shows, line
16 in the improved TestProc was executed only once instead of 10,000 times
and it took only 584 ms. instead of 5,852 ms., as line 18 did in the original
TestProc.
Profiling with SQL*Plus
So far the runs have been made with TOAD. There are situations, however,
where you'll want to start a profiling process outside of TOAD in order
to control the profiling session more—for instance, by profiling multiple
procedures in batch mode, opening multiple SQL*Plus sessions and running
profilings in parallel, etc. With TOAD you are limited to one instance
of the program running and one procedure profiling at a time.
To profile outside of TOAD, you need to do TOAD's work by yourself:
1 - Add a wrapper around the procedure call, utilizing the START_PROFILER
and STOP_PROFILER procedures of the DBMS_PROFILER package.
2 - Insert additional code to calculate totals, load source code, and
do the cleanup.
I created the stored procedures ProfilerUnitsTotals (Listing
3) and ProfilerLoadSource (Listing 4) to do
the second item. You may consider creating your custom profiling package
where you can put these procedures and add more utilities later.
After doing this, you can use TOAD's nice graphic profiling interface,
even though you will be running your procedure from SQL*Plus.
Listing 3. The ProfilerUnitsTotals procedure
code.
CREATE OR REPLACE PROCEDURE ProfilerUnitsTotals(
p_RunId IN INTEGER,
p_ProcedureName VARCHAR2 DEFAULT 'Unknown') IS
CURSOR UnitsTotalCursor (p_Id BINARY_INTEGER) IS
SELECT Unit_Number AS UnitNumber, SUM(Total_Time) AS
UnitTimeTotal
FROM PLSQL_Profiler_Data
WHERE RunId = p_Id
GROUP BY Unit_Number;
BEGIN
IF NVL(p_RunId, 0) > 0 THEN
FOR v_ProfilerUnitsRec
IN UnitsTotalCursor(p_RunId)
LOOP
UPDATE
PLSQL_Profiler_Units
SET Total_Time = v_ProfilerUnitsRec.UnitTimeTotal
WHERE RunId = p_RunId
AND Unit_Number = v_ProfilerUnitsRec.UnitNumber;
END LOOP;
UPDATE PLSQL_Profiler_Runs
SET Run_User =
User,
Run_Proc = p_ProcedureName
WHERE RunId = p_RunId;
COMMIT;
ELSE
DBMS_OUTPUT.PUT_LINE('Parameter
value :' || TO_CHAR(p_RunId) || ' is invalid.');
END IF;
EXCEPTION
WHEN OTHERS THEN
DBMS_OUTPUT.PUT_LINE('Error
' || TO_CHAR(SQLCODE) || ': ' || SQLERRM);
END ProfilerUnitsTotals;
/
Listing 4. The ProfilerLoadSource procedure code.
CREATE OR REPLACE PROCEDURE ProfilerLoadSource(
p_RunId IN INTEGER DEFAULT NULL) IS
v_RunId INTEGER := 0;
CURSOR csr_LastRun IS
SELECT MAX(RunId)
FROM PLSQL_Profiler_Runs;
CURSOR csr_SourceLineCursor (p_Id BINARY_INTEGER) IS
SELECT D.Unit_Number, D.Line#, S.Text
FROM PLSQL_Profiler_Units U, PLSQL_Profiler_Data
D, User_Source S
WHERE U.RunId = D.RunId
AND U.Unit_Number = D.Unit_Number
AND U.Unit_Name
= S.Name
AND U.Unit_Type
= S.Type
AND D.Line#
= S.Line
AND U.RunId
= p_Id;
BEGIN
IF p_RunId IS NULL THEN
OPEN csr_LastRun;
FETCH csr_LastRun INTO v_RunId;
CLOSE csr_LastRun;
ELSE
v_RunId := p_RunId;
END IF;
IF NVL(v_RunId, 0) > 0 THEN
DELETE
FROM PLSQL_Profiler_Data
WHERE RunId = v_RunId
AND Total_Occur = 0;
FOR v_ProfilerSourceLine IN csr_SourceLineCursor(v_RunId)
LOOP
UPDATE PLSQL_Profiler_Data
SET Text = v_ProfilerSourceLine.Text
WHERE RunId = v_RunId
AND Unit_Number = v_ProfilerSourceLine.Unit_Number
AND Line# = v_ProfilerSourceLine.Line#;
END LOOP;
COMMIT;
ELSE
DBMS_OUTPUT.PUT_LINE('Parameter value
:' || TO_CHAR(v_RunId) || ' is invalid.');
END IF;
EXCEPTION
WHEN OTHERS THEN
DBMS_OUTPUT.PUT_LINE('Error
' || TO_CHAR(SQLCODE) || ': ' || SQLERRM);
END ProfilerLoadSource;
/
Start SQL*Plus, connect to the database as the same user connected via TOAD, and execute the PL/SQL anonymous block shown in Listing 5.
Listing 5. The PL/SQL code that profiles the TestProc stored procedure.
DECLARE
v_RunId INTEGER := 0;
v_Procedure VARCHAR2(30) := 'TestProc';
v_Procedure_Desc VARCHAR2(30) := ' Improved';
v_Run POSITIVE := 1;
v_App VARCHAR2(30) := 'SQL*Plus';
v_RunTitle VARCHAR2(2047) := v_App || ', ' || v_Procedure
|| v_Procedure_Desc || ' Run ' || TO_CHAR(v_Run) || ' - ' ||
TO_CHAR(SYSDATE, 'MM/DD/YYYY');
v_Comment VARCHAR2(2047) := 'Comment for ' || v_RunTitle
|| '.';
BEGIN
DBMS_PROFILER.START_PROFILER(v_RunTitle, v_Comment,
v_RunId);
DBMS_OUTPUT.PUT_LINE('Profiler Run ID: ' || TO_CHAR(v_RunId));
/* actual procedure for profiling executes here */
TestProc(10000);
DBMS_PROFILER.STOP_PROFILER();
ProfilerUnitsTotals(v_RunId, v_Procedure);
ProfilerLoadSource(v_RunId);
END;
/
Now you can look at the profiling data generated by SQL*Plus' runs via the graphical TOAD interface.
From (Figure 5: A line-by-line analysis of the improved TestProc, SQL*Plus runs 8–10) it's clear that all six runs of the improved version of TestProc (TOAD runs 4–6 and SQL*Plus runs 8–10) are 10–12 times faster than the original version (runs 1–3). This happened because we were able to locate the problem (line 18) using the Profiler and solve it, with a consequent significant performance gain.
As you can see, Oracle 8i Profiler is a powerful tool that allows Oracle database developers to collect execution time statistics, identify bottlenecks, and tune PL/SQL code efficiently.