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
as
begin
dbms_lock.sleep(5);
return trunc(dbms_random.value(1,10));
end;
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.
Summary:
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.
Comments