In all books that I red about performance tuning in Oracle (and other major vendor) relational databases, you can find that when optimizing SQL, you remove the select part and concentrate on part starting with FROM clause to inspect what tables have been involved along with the WHERE clause.

Recently I have a interesting case where I need to join 4 large (several hundreds of million) tables, with poor (not selective) joins among them.

That query take a week to end, and it take a while for me to figure out what is going on.

Here I’ll create a very simple version of the issue I had, to concentrate only on important part of the issue, that will prove that statement from optimization books, although valid in majority of cases, are far from truth in this particular case.

I’ll use EMP table from the SCOTT sample schema.

grant execute on dbms_lock to scott;

All commands to the end of the blog can be executed as SCOTT user.

create or replace function flock 
return number 
return trunc(dbms_random.value(1,10));

For each call, function flock will wait for a 5 seconds, and then return random number in the interval from 1 – 10.

Then I need to call the function from the SQL:

select /*+ test1 */ flock, e.* from emp e where rownum < 3;
Elapsed 10,112 sec 

To return 2 rows, query runs for 10,1 second.

Let’s see the execution plan (with gather hint):

SQL_ID  4fbxxh18mw6fv, child number 0
select /*+ test1 */ flock, e.* from emp e where rownum < 3
Plan hash value: 1973284518
| Id  | Operation          | Name | Starts | E-Rows | A-Rows |   A-Time   | Buffers |
|   0 | SELECT STATEMENT   |      |      1 |        |      2 |00:00:00.01 |       3 |
|*  1 |  COUNT STOPKEY     |      |      1 |        |      2 |00:00:00.01 |       3 |
|   2 |   TABLE ACCESS FULL| EMP  |      1 |      2 |      2 |00:00:00.01 |       3 |

From execution plan, as can be seen, with all timings enabled, I can’t see where the times is spent.

The only option here is to trace statement execution.

After the tracing and after format trace file with TKPROF, I can see that 10,01 second is elapsed time for the statement, but I still can’t see where the time is spent.

call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        1      0.00       0.00          0          0          0           0
Execute      1      0.00       0.00          0          0          0           0
Fetch        1      0.00      10.01          0          3          0           2
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        3      0.00      10.01          0          3          0           2

Fortunately, the following section of TKPROF output provides the clue what is really going on.

Elapsed times include waiting on following events:
  Event waited on                             Times   Max. Wait  Total Waited
  ----------------------------------------   Waited  ----------  ------------
  SQL*Net message to client                       1        0.00          0.00
  PL/SQL lock timer                               2        5.01         10.01
  SQL*Net message from client                     1        0.00          0.00


On the following picture (based on Trace profiling), you can see PL/SQL lock timer event (2 executions, once per each row, where each execution takes 5 seconds).

Now it’s clear that almost all time has spent on PL/SQL dbms_lock waiting.

To see exactly function name, you can use HPROF and put SQL inside the procedure.



It is always necessary to take a deep look at the query you try to optimize, to get familiar with.

Although it will postpone real work on tuning, it can save hours in more complex query.

And it is important not to forget that calling PL/SQL function from the SQL is row-by-row operation, not set-by-set as we expect from the SQL.

There are various ways to optimize that part also, but that will be covered in one of the future blogs.

Get notified when a new post is published!



There are no comments yet. Why not start the discussion?

Leave a Reply

Your email address will not be published. Required fields are marked *

This site uses Akismet to reduce spam. Learn how your comment data is processed.