Clock watching – Instrumenting PL/SQL with timing information

You know what it’s like, that piece of code you wrote last week and simply whizzed along in the Development environment is now running like a dog in test. You want to get a quick pointer as to where the bottle-neck is before you get up to your elbows in trace files.

In my experience, there’s a better than even chance that your problem is caused by some issue with an index – i.e. it’s missing / disabled/ stats are out of date. Checking the index is a bit like starting to work out why you can’t switch on the TV by checking that it’s plugged in. But I digress.
If it’s a bit of straight SQL, the easiest way to check how fast it is, is to SET TIMING ON in SQL*Plus and just run it. But what if your problem is in a PL/SQL block containing multiple SQL statement ?
It’s at this point, you congratulate yourself for listening to that nice Mr Kyte when he was going on about “instrumentation”.
You know that Oracle now has this nice little function that returns the time in 100ths of a second ( DBMS_UTILITY.GET_TIME) and that you can include conditional compiler directives to induce your carefully crafted masterpiece to spit out loads of useful info.
Furthermore, you’ve written a function to return the difference between two DBMS_UTILITY.GET_TIME values, and looks something like this :-

CREATE OR REPLACE FUNCTION pls_timing( p_start IN PLS_INTEGER,  p_end IN PLS_INTEGER) RETURN VARCHAR2 IS
   l_elapsed PLS_INTEGER;
   l_huns PLS_INTEGER;
   l_secs PLS_INTEGER;
   l_mins PLS_INTEGER;
   l_hrs PLS_INTEGER;
   l_formatted_time VARCHAR2(20);    
BEGIN
   l_elapsed := p_end - p_start;
   l_huns := MOD( l_elapsed, 100);
   l_secs := FLOOR(MOD( l_elapsed, 6000)/ 100);
   l_mins := FLOOR(FLOOR( MOD( l_elapsed , 360000))/6000);
   l_hrs := FLOOR(l_elapsed / 360000);
   l_formatted_time := LPAD(l_hrs, 2, '0')||':'||LPAD( l_mins, 2, '0')||':'||LPAD( l_secs, 2, '0')||'.'||LPAD( l_huns,2,'0');
   RETURN l_formatted_time;
END;

All in all, you’re a bit of a clever-clogs really.
Now all you need to do is fire up SQL*Plus and away you go.

Your code will probably look something like this :-

set serveroutput on size 1000000
--
-- slow.sql
-- PL/SQL script to demonstrate usage of timing package in conjunction
-- with conditional compilation
--
ALTER SESSION SET PLSQL_CCFLAGS = 'debug:TRUE'
/

DECLARE
   l_start PLS_INTEGER;
   l_end PLS_INTEGER;
   l_elapsed VARCHAR2(100);
BEGIN
   $IF $$debug $THEN
      l_start := DBMS_UTILITY.GET_TIME;
   $END    
   --
   -- This is where your SQL would normally go.
   -- If you want to run this example as is, make sure you have
   -- execute privileges on DBMS_LOCK
   --
   DBMS_LOCK.SLEEP(5);
   $IF $$debug $THEN
      l_end := DBMS_UTILITY.GET_TIME;
      l_elapsed := pls_timing( l_start, l_end);
      DBMS_OUTPUT.PUT_LINE(l_elapsed);
   $END
   DBMS_OUTPUT.PUT_LINE('Yawn! is it that time already ?');
END;    
/ 

The output will probably be something like :-

SQL> @slow.sql

Session altered.

00:00:05.01

Yawn! is it that time already ?

PL/SQL procedure successfully completed.

SQL>

Note the ALTER SESSION SET PL_CC_FLAGS='debug:TRUE'.
This effectively declares a variable called debug to be used at compile time and sets it’s value to TRUE.
So, when the compiler comes across the line
$IF $$debug $THEN it evaluates this to TRUE and processes the commands up to the
$END
If the problem is code related ( and it usually is), you should get a fair idea of where to start looking.
Which reminds me, at some point I will be writing something about factors affecting performance…don’t hold your breath, it’s not earth-shattering.

About these ads

Leave a Reply

Fill in your details below or click an icon to log in:

WordPress.com Logo

You are commenting using your WordPress.com account. Log Out / Change )

Twitter picture

You are commenting using your Twitter account. Log Out / Change )

Facebook photo

You are commenting using your Facebook account. Log Out / Change )

Google+ photo

You are commenting using your Google+ account. Log Out / Change )

Connecting to %s