Search My Oracle Blog

Custom Search

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

Aggregated by orafaq.com

Aggregated by orafaq.com
This blog is being aggregated by orafaq.com

Top 50 Oracle SQL Blogs 2016

Top 50 Oracle SQL Blogs 2016
Top 50 Oracle SQL Blogs 2016