Database Journal
MS SQL Oracle DB2 Access MySQL PostgreSQL Sybase PHP SQL Etc SQL Scripts & Samples Links Database Forum

» Database Journal Home
» Database Articles
» Database Tutorials
MS SQL
Oracle
DB2
MS Access
MySQL
» RESOURCES
Database Tools
SQL Scripts & Samples
Links
» Database Forum
» Sitemap
Free Newsletters:
DatabaseDaily  
News Via RSS Feed


follow us on Twitter
Database Journal |DBA Support |SQLCourse |SQLCourse2
 

Featured Database Articles

Oracle

Posted Sep 24, 2008

Unleashing DBMS_PROFILER

By Steve Callan

Anyone who’s been involved with Oracle over the past decade has seen a huge improvement in the ability to capture performance data. We can explain, trace, debug, advise, and profile. Most of the attention still seems to be on SQL, and probably rightly so because that is the end purpose of a database, right? Select, insert, update and delete data is what it’s all about. However, what frequently goes hand in hand with SQL is (no surprise here) PL/SQL.

Quite often, performance tuning examples dwell on what’s taking place with SQL statements, and along with that, reporting on wait events. The examples show the use of explain plans, TKPROF’d trace files, and at a higher level, AWR or STATSPACK reports. But what’s going on with the PL/SQL? That’s where DBMS_PROFILER comes into play. Other utilities such as DBMS_DEBUG are related to profiling, and some tools, such as Forms Builder, enable developers to debug or step through code a line at a time.

All those “little” things you do inside a block of code – instring this, substring that, concatenate strings, over and over if inside a loop – how much time is being spent on that? By using DBMS_PROFILER, you can see where all of the time goes, and not just all of the SQL time. Further, not only can you see the results by querying from a table (or tables), but you can generate an HTML-based report with the results neatly arrayed just like within an AWR report. So, what does it take to use DBMS_PROFILER?

Oracle’s documentation mentions this built-in in two places: the PL/SQL User’s Guide and Reference guide and the PL/SQL Packages and Types Reference guide. The overview in the 10g packages and types reference guide states:

This package enables the collection of profiler (perfoprmance) [sic] data for performance improvement or for determining code coverage for PL/SQL applications. Application developers can use code coverage data to focus their incremental testing efforts.

With this interface, you can generate profiling information for all named library units that are executed in a session. The profiler gathers information at the PL/SQL virtual machine level. This information 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.

Not only do we get performance, we get “perfoprmance.” Maybe that’s undocumented performance? Anyway, the steps include installing the package (if not already done), creating three tables via a provided script, invoking the package’s subprograms (e.g., start, stop and flush), and viewing the results.

If performing “SQL> desc dbms_profiler” as SYS or SYSTEM doesn’t return any output, then install the package by running the profload.sql script as SYS in $ORACLE_HOME/rdbms/admin. To create the tables, run the proftab.sql script (same place, BUT as the user performing the profiling, NOT as SYS). This script creates three tables and one sequence, and is re-runnable (it attempts to drop the objects before creating them). The three tables are PLSQL_PROFILER_RUNS, PLSQL_PROFILER_UNITS, and PLSQL_PROFILER_DATA. The subprograms are shown below. Ref: Chapter 73 of Oracle® Database PL/SQL Packages and Types Reference 10g Release 2 (10.2)

Subprogram

Description

FLUSH_DATA

Flushes profiler data collected in the user’s session

GET_VERSION

Gets the version of the API

INTERNAL_VERSION_CHECK

Verifies this version works in the database

PAUSE_PROFILER

Pauses profiler data collection

RESUME_PROFILER

Resumes profiler data collection

START_PROFILER

Starts data collection in the user’s session

STOP_PROFILER

Stops data collection in the user’s session

Now that the framework is in place, we’re ready to give it a spin. Let’s use a BULK version row-by-row block of code for testing, and this comes from Example 11-3 in the 10g PL/SQL user’s guide. Instead of 500 (too small of a value, may get 0 seconds returned for the bulk step), we’ll use 500,000 iterations. On a warmed-up system, the times are around 25 seconds versus 4 seconds.

CREATE TABLE parts1 (pnum INTEGER, pname VARCHAR2(15));
CREATE TABLE parts2 (pnum INTEGER, pname VARCHAR2(15));
DECLARE
  TYPE NumTab IS TABLE OF parts1.pnum%TYPE INDEX BY PLS_INTEGER;
  TYPE NameTab IS TABLE OF parts1.pname%TYPE INDEX BY PLS_INTEGER;
  pnums  NumTab;
  pnames NameTab;
--Not big enough: iterations CONSTANT PLS_INTEGER := 500;
  iterations CONSTANT PLS_INTEGER := 500000;
  t1 INTEGER;
  t2 INTEGER;
  t3 INTEGER;
BEGIN
  FOR j IN 1..iterations LOOP  -- load index-by tables
     pnums(j) := j;
     pnames(j) := 'Part No. ' || TO_CHAR(j);
  END LOOP;
  t1 := DBMS_UTILITY.get_time;
  FOR i IN 1..iterations LOOP  -- use FOR loop
     INSERT INTO parts1 VALUES (pnums(i), pnames(i));
  END LOOP;
  t2 := DBMS_UTILITY.get_time;
  FORALL i IN 1..iterations  -- use FORALL statement
     INSERT INTO parts2 VALUES (pnums(i), pnames(i));
  t3 := DBMS_UTILITY.get_time;
  DBMS_OUTPUT.PUT_LINE('Execution Time (secs)');
  DBMS_OUTPUT.PUT_LINE('---------------------');
  DBMS_OUTPUT.PUT_LINE('FOR loop: ' || TO_CHAR((t2 - t1)/100));
  DBMS_OUTPUT.PUT_LINE('FORALL:   ' || TO_CHAR((t3 - t2)/100));
  COMMIT;
END;
/

The other modification that needs to be made is the addition of the start and stop calls for DBMS_PROFILER. Add in “DBMS_PROFILER.START_PROFILER(sysdate, ‘where’);” and “DBMS_PROFILER.STOP_PROFILER” statements where appropriate and repeat the run (create the tables once, then add delete or truncate statements at the beginning). In the example below (only the BEGIN section is shown, DECLARE stays the same except for adding two “run” variables), I added three captures: time to load the tables, and times for each of the inserts.

  run_comment VARCHAR2(30) := to_char(sysdate);
  run_comment1 VARCHAR2(30);
BEGIN
  DBMS_PROFILER.START_PROFILER
  (run_comment,'Load tables');
  FOR j IN 1..iterations LOOP  -- load index-by tables
     pnums(j) := j;
     pnames(j) := 'Part No. ' || TO_CHAR(j);
  END LOOP;
  DBMS_PROFILER.STOP_PROFILER;
  t1 := DBMS_UTILITY.get_time;
  DBMS_PROFILER.START_PROFILER(run_comment,'For Loop');
  FOR i IN 1..iterations LOOP  -- use FOR loop
     INSERT INTO parts1 VALUES (pnums(i), pnames(i));
  END LOOP;
  DBMS_PROFILER.STOP_PROFILER;
  t2 := DBMS_UTILITY.get_time;
  DBMS_PROFILER.START_PROFILER(run_comment,'Forall');
  FORALL i IN 1..iterations  -- use FORALL statement
     INSERT INTO parts2 VALUES (pnums(i), pnames(i));
  DBMS_PROFILER.STOP_PROFILER;
  t3 := DBMS_UTILITY.get_time;
  DBMS_OUTPUT.PUT_LINE('Execution Time (secs)');
  DBMS_OUTPUT.PUT_LINE('---------------------');
  DBMS_OUTPUT.PUT_LINE('FOR loop: ' || TO_CHAR((t2 - t1)/100));
  DBMS_OUTPUT.PUT_LINE('FORALL:   ' || TO_CHAR((t3 - t2)/100));
  COMMIT;
END;
/

What are the results? We could query the tables directly, but that’s not very interesting. Using Toad, the data appears as so:

PLSQL_PROFILER_RUNS

PLSQL_PROFILER_RUNS

 

PLSQL_PROFILER_UNITS

PLSQL_PROFILER_UNITS

 

PLSQL_PROFILER_DATA (ordered by RUNID ascending)

PLSQL_PROFILER_DATA (ordered by RUNID ascending)

Kind of dull in a way. But there is a way to have the format shown in HTML. MetaLink note 243755.1, “Implementing and Using the PL/SQL Profiler,” contains a downloadable ZIP file, with a SQL script to take a run and generate HTML output. You can run profiler.sql as is and enter a run ID, or pass the ID in as a parameter.

SQL> @profiler
     RUNID RUN_DATE           RUN_COMMENT
---------- ------------------ -----------
         2 17-SEP-08 17:36:28 17-SEP-08
         3 17-SEP-08 17:36:29 17-SEP-08
         4 17-SEP-08 17:36:59 17-SEP-08

Usage:
sqlplus apps/
SQL> START profiler.sql 
Enter value for 1:

The script generates a file named profiler_X.html, with X being the selected run ID. The contents of run ID 3 (using the for loop) appear as so:

profiler_X.html

Looks better, but what happened statement by statement? For that, we need to add in one item, and that is compile with debug. I’ll turn the anonymous block into a procedure and capture the start and stop overall for the looping process (don’t care about the inserts as that is overhead for both parts).

CREATE or REPLACE PROCEDURE profiler_demo
AS
  TYPE NumTab IS TABLE OF parts1.pnum%TYPE INDEX BY PLS_INTEGER;
  TYPE NameTab IS TABLE OF parts1.pname%TYPE INDEX BY PLS_INTEGER;
  pnums  NumTab;
  pnames NameTab;
  iterations CONSTANT PLS_INTEGER := 500000;
  t1 INTEGER;
  t2 INTEGER;
  t3 INTEGER;
  run_comment VARCHAR2(30) := to_char(sysdate);
  run_comment1 VARCHAR2(30);
BEGIN
  execute immediate 'truncate table parts1 reuse storage';
  execute immediate 'truncate table parts2 reuse storage';
  FOR j IN 1..iterations LOOP  -- load index-by tables
     pnums(j) := j;
     pnames(j) := 'Part No. ' || TO_CHAR(j);
  END LOOP;
  t1 := DBMS_UTILITY.get_time;
  DBMS_PROFILER.START_PROFILER(run_comment,'Start of Loops');
  FOR i IN 1..iterations LOOP  -- use FOR loop
     INSERT INTO parts1 VALUES (pnums(i), pnames(i));
  END LOOP;
  t2 := DBMS_UTILITY.get_time;
  FORALL i IN 1..iterations  -- use FORALL statement
     INSERT INTO parts2 VALUES (pnums(i), pnames(i));
  DBMS_PROFILER.STOP_PROFILER;
  t3 := DBMS_UTILITY.get_time;
  DBMS_OUTPUT.PUT_LINE('Execution Time (secs)');
  DBMS_OUTPUT.PUT_LINE('---------------------');
  DBMS_OUTPUT.PUT_LINE('FOR loop: ' || TO_CHAR((t2 - t1)/100));
  DBMS_OUTPUT.PUT_LINE('FORALL:   ' || TO_CHAR((t3 - t2)/100));
  COMMIT;
END;
/

Compile the procedure with DEBUG (alter procedure profiler_demo compile_debug) and then run profiler again. The output will be exactly what we’re looking for in terms of line by line detail and timings. You have to admit this is MUCH better than pouring through a formatted trace file to see where all of the time went.

line by line detail and timings

In Closing

The DBMS_PROFILER package has been around since at least Oracle8i days. For some reason, it seems to get short shrift in many of the tuning books and online discussion forums. After seeing how easy it is to implement, perhaps you’ll add this built-in to your tuning arsenal. Other variations of using this include joining the profiler tables to USER_SOURCE or ALL_SOURCE yourself (which is what takes place in the profiler script; use that as a starting point if so desired), drilling down to the worst or most time consuming lines, and using three scripts contained in the plsql/demo directory (profdemo, profrep and profsum.sql).

Also buried inside the demo directory are the remnants of a Java-based viewing utility. There was a profview.html in older versions (not present at least in 10g Windows), a Windows batch file (profview_nt.bat), and a jar file (profview.jar). The batch file will error out with a failure to load the Main-Class manifest from profview.jar. The command to run the viewer (assuming you can fix the manifest error, or happen to have an older version of this and want to modernize it) is java riw. Overall, the HTML output is probably the easiest and quickest means of viewing the profile information in a better-than-text-only interface.

» See All Articles by Columnist Steve Callan



Oracle Archives

Comment and Contribute

 


(Maximum characters: 1200). You have characters left.

 

 




Latest Forum Threads
Oracle Forum
Topic By Replies Updated
Oracle Data Mining: Classification jan.hasller 0 July 5th, 07:19 AM
Find duplicates - Unique IDs Lava 5 July 2nd, 08:30 AM
no matching unique or primary key rcanter 1 April 25th, 12:32 PM
Update values of one table based on condition of values in other table using Trigger Gladiator 3 February 29th, 06:01 PM


















Thanks for your registration, follow us on our social networks to keep up-to-date