14 April, 2010

SQLs in PLSQL -- 2

Building on the demo PLSQL procedure in my previous SQLs in PLSQL post, I show how Oracle converts 3 "similar" statements to the "same" statement !

If I create 3 "similar" INSERT statements in my procedure and execute it as :

SQL> create or replace procedure PLSQL_SQL_bind_2
2 as
3 l_entry_id number;
4 l_entry_text varchar2(500);
5
6 cursor c1 is
7 select object_id, owner||object_name from dba_objects where object_type = 'VIEW' order by object_id;
8
9 begin
10 open c1;
11 loop
12 fetch c1 into l_entry_id,l_entry_text;
13 exit when c1%NOTFOUND;
14 insert into log_table values (l_entry_id, l_entry_text);
15 l_entry_id := l_entry_id+100000;
16 insert into LOG_TABLE VALUES
17 (l_entry_id, l_entry_text);
18 l_entry_id := l_entry_id + 200000;
19 insert into
20 Log_Table
21 Values
22 (L_Entry_ID,
23 L_Entry_TEXT);
24 end loop;
25 commit;
26 end;
27 /

Procedure created.

SQL>
SQL> select count(*) from dba_objects where object_type = 'VIEW';

COUNT(*)
----------
3697

SQL> alter session set sql_trace=TRUE;

Session altered.

SQL> execute PLSQL_sql_bind_2;

PL/SQL procedure successfully completed.

SQL>


I find that tkprof of the Trace shows :

SELECT OBJECT_ID, OWNER||OBJECT_NAME
FROM
DBA_OBJECTS WHERE OBJECT_TYPE = 'VIEW' ORDER BY OBJECT_ID


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 3698 0.25 0.24 0 5407 0 3697
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 3700 0.26 0.25 0 5407 0 3697

Misses in library cache during parse: 1
Optimizer mode: ALL_ROWS

INSERT INTO LOG_TABLE
VALUES
(:B2 , :B1 )


call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 3 0.00 0.00 0 0 0 0
Execute 11091 0.43 0.40 0 208 12239 11091
Fetch 0 0.00 0.00 0 0 0 0
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 11094 0.43 0.40 0 208 12239 11091

Misses in library cache during parse: 1
Misses in library cache during execute: 1
Optimizer mode: ALL_ROWS


Exactly the same "INSERT" statement executed 11,091 (i.e. 3697*3) times !
But why are there 3 different PARSEs ?

This is what the raw Trace file shows :

PARSING IN CURSOR #12 len=99 dep=1 uid=64 oct=3 lid=64 tim=1241463209324952 hv=608974888 ad='8f7363d0'
SELECT OBJECT_ID, OWNER||OBJECT_NAME FROM DBA_OBJECTS WHERE OBJECT_TYPE = 'VIEW' ORDER BY OBJECT_ID
END OF STMT
PARSE #12:c=12998,e=12188,p=0,cr=2,cu=0,mis=1,r=0,dep=1,og=1,tim=1241463209324936
EXEC #12:c=0,e=131,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=1,tim=1241463209325440
FETCH #12:c=219967,e=215466,p=0,cr=5407,cu=0,mis=0,r=1,dep=1,og=1,tim=1241463209541097

PARSING IN CURSOR #10 len=41 dep=1 uid=64 oct=2 lid=64 tim=1241463209542024 hv=4147238877 ad='942837f8'
INSERT INTO LOG_TABLE VALUES (:B2 , :B1 )
END OF STMT
PARSE #10:c=0,e=441,p=0,cr=0,cu=0,mis=1,r=0,dep=1,og=1,tim=1241463209542012

PARSING IN CURSOR #13 len=227 dep=2 uid=0 oct=3 lid=0 tim=1241463209543228 hv=2190775527 ad='8f5fb7c8'
select u.name,o.name, t.update$, t.insert$, t.delete$, t.enabled from obj$ o,user$ u,trigger$ t where t.baseobject=:1 and t.obj#=o.obj# and o.owner#=u.user# and bitand(property,16)=0 and bitand(property,8)=0 order by o.obj#
END OF STMT
PARSE #13:c=0,e=416,p=0,cr=0,cu=0,mis=1,r=0,dep=2,og=4,tim=1241463209543221
EXEC #13:c=3999,e=4077,p=0,cr=0,cu=0,mis=1,r=0,dep=2,og=4,tim=1241463209547660
FETCH #13:c=0,e=105,p=0,cr=1,cu=0,mis=0,r=0,dep=2,og=4,tim=1241463209547905

EXEC #10:c=7998,e=7968,p=0,cr=2,cu=22,mis=1,r=1,dep=1,og=1,tim=1241463209550338

PARSING IN CURSOR #2 len=41 dep=1 uid=64 oct=2 lid=64 tim=1241463209550701 hv=4147238877 ad='942837f8'
INSERT INTO LOG_TABLE VALUES (:B2 , :B1 )
END OF STMT
PARSE #2:c=0,e=115,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=1,tim=1241463209550695
EXEC #2:c=1000,e=153,p=0,cr=1,cu=3,mis=0,r=1,dep=1,og=1,tim=1241463209551180

PARSING IN CURSOR #3 len=41 dep=1 uid=64 oct=2 lid=64 tim=1241463209551343 hv=4147238877 ad='942837f8'
INSERT INTO LOG_TABLE VALUES (:B2 , :B1 )
END OF STMT
PARSE #3:c=0,e=29,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=1,tim=1241463209551338
EXEC #3:c=0,e=113,p=0,cr=1,cu=3,mis=0,r=1,dep=1,og=1,tim=1241463209551868

FETCH #12:c=0,e=26,p=0,cr=0,cu=0,mis=0,r=1,dep=1,og=1,tim=1241463209552009
EXEC #10:c=0,e=39,p=0,cr=0,cu=1,mis=0,r=1,dep=1,og=1,tim=1241463209552170
EXEC #2:c=0,e=28,p=0,cr=0,cu=1,mis=0,r=1,dep=1,og=1,tim=1241463209552298
EXEC #3:c=0,e=25,p=0,cr=0,cu=1,mis=0,r=1,dep=1,og=1,tim=1241463209552414
FETCH #12:c=0,e=7,p=0,cr=0,cu=0,mis=0,r=1,dep=1,og=1,tim=1241463209552517
EXEC #10:c=0,e=31,p=0,cr=0,cu=1,mis=0,r=1,dep=1,og=1,tim=1241463209552631
EXEC #2:c=0,e=38,p=0,cr=0,cu=1,mis=0,r=1,dep=1,og=1,tim=1241463209552760
EXEC #3:c=0,e=24,p=0,cr=0,cu=1,mis=0,r=1,dep=1,og=1,tim=1241463209552873


with the Cursors repeatedly being executed as :

FETCH #12
EXEC #10
EXEC #2
EXEC #3



Cursor 12 is the SQL for the PLSQL Cursor c1 in my procedure.
Cursors 10, 2 and 3 are the three INSERT statements.
Note that all three have the same HashValue (hv=4147238877) !

Oracle's PLSQL engine converted the 3 INSERT statements (which are literally dissimilar) into the exactly same SQL statement which needed a Hard Parse only once and Soft Parse twice thereafter. Then, for each of the 11,091 Executions, no further parse was needed.

Go back and look at the 3 different INSERT statements in the procedure and note the single INSERT statement (hv=4147238877) !

Thus, Oracle is smart enough to convert SQL statements in a PLSQL procedure (or block) into *reusable* SQLs which do not need to be parsed 11thousand times.

.
.
.

2 comments:

Roberto said...

For your information here:
http://tonyhasler.wordpress.com/2010/01/17/identifying-the-sql_id-of-static-sql-in-plsql-blocks/
there is a interesting discussion on SQLs inside PL/SQL.
I have tested your example with sql_util.get_last_sqltext function (actually my modified version to return only SQL_ID). SQL_IDs was always the same, of course:
create or replace procedure PLSQL_SQL_bind_2_1
[...]
insert into log_table values (l_entry_id, l_entry_text);
l_entry_id := l_entry_id+100000;
DBMS_OUTPUT.put_line(sql_util.get_last_sql_id);
insert into LOG_TABLE VALUES
(l_entry_id, l_entry_text);
l_entry_id := l_entry_id + 200000;
DBMS_OUTPUT.put_line(sql_util.get_last_sql_id);
insert into
Log_Table
Values
(L_Entry_ID,
L_Entry_TEXT);
DBMS_OUTPUT.put_line(sql_util.get_last_sql_id);
[...]

exec execute PLSQL_sql_bind_2_1
10fy21mvm3pyx
10fy21mvm3pyx
10fy21mvm3pyx
10fy21mvm3pyx
10fy21mvm3pyx
10fy21mvm3pyx
10fy21mvm3pyx
...

Best regards

Hemant K Chitale said...

Yes, the same SQL statement was executed each time.

Hemant