First, I setup the test data :
SQL> create or replace function ten_days_ago_date(date_in date) return date DETERMINISTICI now have 19 rows and will be applying a DETERMINISTIC function to the date column "created" when I query the table.
2 as
3 deducted_date date;
4 begin
5 select date_in - 10 into deducted_date from dual;
6 return deducted_date;
7 end;
8 /
Function created.
SQL>
SQL>
SQL> drop table my_objects purge;
Table dropped.
SQL>
SQL> create table my_objects (obj_id number , obj_name varchar2(30), created date);
Table created.
SQL>
SQL> insert into my_objects
2 select object_id, object_name,created
3 from dba_objects
4 where owner in ('HEMANT','SCOTT')
5 /
19 rows created.
SQL>
SQL> exec dbms_session.session_trace_enable;
PL/SQL procedure successfully completed.
SQL> select obj_id, created, ten_days_ago_date(created)
2 from my_objects
3 order by created
4 /
OBJ_ID CREATED TEN_DAYS_
---------- --------- ---------
73180 13-AUG-09 03-AUG-09
73179 13-AUG-09 03-AUG-09
73181 13-AUG-09 03-AUG-09
73182 13-AUG-09 03-AUG-09
73183 13-AUG-09 03-AUG-09
73184 13-AUG-09 03-AUG-09
82749 06-JUL-10 26-JUN-10
82748 06-JUL-10 26-JUN-10
82751 06-JUL-10 26-JUN-10
85339 14-OCT-10 04-OCT-10
85340 14-OCT-10 04-OCT-10
85341 14-OCT-10 04-OCT-10
85344 05-FEB-11 26-JAN-11
85346 05-FEB-11 26-JAN-11
85429 05-APR-11 26-MAR-11
85434 09-APR-11 30-MAR-11
85439 09-APR-11 30-MAR-11
85444 09-APR-11 30-MAR-11
85451 09-APR-11 30-MAR-11
19 rows selected.
SQL> exec dbms_session.session_trace_disable;
PL/SQL procedure successfully completed.
SQL>
I have 6 rows with the date '13-AUG-09', 3 of '06-JUL-10', 3 of '14-OCT-10', 3 of '05-FEB-11' and 4 of '09-APR-11'.
select obj_id, created, ten_days_ago_date(created)
from my_objects
order by created
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 1 0.02 0.23 0 1 0 0
Execute 1 0.00 0.00 0 0 0 0
Fetch 3 0.01 0.02 0 7 0 19
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 5 0.04 0.25 0 8 0 19
Misses in library cache during parse: 1
Optimizer mode: ALL_ROWS
Parsing user id: 184
Rows Row Source Operation
------- ---------------------------------------------------
19 SORT ORDER BY (cr=7 pr=0 pw=0 time=0 us cost=4 size=418 card=19)
19 TABLE ACCESS FULL MY_OBJECTS (cr=7 pr=0 pw=0 time=576 us cost=3 size=418 card=19)
SQL ID: 7dq8qm13md0cf
Plan Hash: 1388734953
SELECT :B1 - 10
FROM
DUAL
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 1 0.00 0.00 0 0 0 0
Execute 12 0.00 0.00 0 0 0 0
Fetch 12 0.00 0.00 0 0 0 12
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 25 0.00 0.00 0 0 0 12
Misses in library cache during parse: 0
Optimizer mode: ALL_ROWS
Parsing user id: 184 (recursive depth: 1)
Rows Row Source Operation
------- ---------------------------------------------------
1 FAST DUAL (cr=0 pr=0 pw=0 time=0 us cost=2 size=0 card=1)
There are 19 rows with 5 distinct dates but the function was executed 12 times ! Isn't there a mismatch ? Should the function have been executed 19 times or 5 times ?
.
.
.
But wait ..... a DATE datatype in Oracle captures Hours:Minutes:Seconds besides Day:Month:Year. Therefore, two rows with the "Date" '09-APR-11' may not necessarily have really the same Date Value stored in the database !
I rerun the query but also print the Hours:Minutes:Seconds and capture the Binds in the trace file.
Here's the tkprof output :
If I look at the raw trace file, however, I can find the points of execution :
SQL> exec dbms_session.session_trace_enable(waits=>TRUE, binds=>TRUE);
PL/SQL procedure successfully completed.
SQL> select obj_id, created, ten_days_ago_date(created), to_char(created,'DD-MON-RR HH24:MI:SS')
2 from my_objects
3 order by created
4 /
OBJ_ID CREATED TEN_DAYS_ TO_CHAR(CREATED,'DD-MON-RRH
---------- --------- --------- ---------------------------
73180 13-AUG-09 03-AUG-09 13-AUG-09 23:35:45
73179 13-AUG-09 03-AUG-09 13-AUG-09 23:35:45
73181 13-AUG-09 03-AUG-09 13-AUG-09 23:35:45
73182 13-AUG-09 03-AUG-09 13-AUG-09 23:35:45
73183 13-AUG-09 03-AUG-09 13-AUG-09 23:35:45
73184 13-AUG-09 03-AUG-09 13-AUG-09 23:35:45
82749 06-JUL-10 26-JUN-10 06-JUL-10 14:28:11
82748 06-JUL-10 26-JUN-10 06-JUL-10 14:28:11
82751 06-JUL-10 26-JUN-10 06-JUL-10 14:28:11
85339 14-OCT-10 04-OCT-10 14-OCT-10 01:27:25
85340 14-OCT-10 04-OCT-10 14-OCT-10 01:40:57
85341 14-OCT-10 04-OCT-10 14-OCT-10 02:18:35
85344 05-FEB-11 26-JAN-11 05-FEB-11 08:04:52
85346 05-FEB-11 26-JAN-11 05-FEB-11 08:18:05
85429 05-APR-11 26-MAR-11 05-APR-11 07:43:23
85434 09-APR-11 30-MAR-11 09-APR-11 08:12:42
85439 09-APR-11 30-MAR-11 09-APR-11 08:39:13
85444 09-APR-11 30-MAR-11 09-APR-11 21:28:01
85451 09-APR-11 30-MAR-11 09-APR-11 21:58:17
19 rows selected.
SQL> exec dbms_session.session_trace_disable;
PL/SQL procedure successfully completed.
SQL>
Here's the tkprof output :
SQL ID: 7dq8qm13md0cf
Plan Hash: 1388734953
SELECT :B1 - 10
FROM
DUAL
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 1 0.00 0.00 0 0 0 0
Execute 12 0.00 0.00 0 0 0 0
Fetch 12 0.00 0.00 0 0 0 12
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 25 0.00 0.00 0 0 0 12
Misses in library cache during parse: 0
Optimizer mode: ALL_ROWS
Parsing user id: 184 (recursive depth: 1)
Rows Row Source Operation
------- ---------------------------------------------------
1 FAST DUAL (cr=0 pr=0 pw=0 time=0 us cost=2 size=0 card=1)
If I look at the raw trace file, however, I can find the points of execution :
=====================That adds up to 12 executions. One execution afresh each time the retrieved value changes. Note : The sequence of values that appear in the trace file isn't exactly the same as that in the SQL output. The trace file shows how the function is applied to each row fetched *before* the rows are sorted. The function is applied before the ORDER BY is applied.
PARSING IN CURSOR #2 len=25 dep=1 uid=184 oct=3 lid=184 tim=1302411557311398 hv=1194754446 ad='2d7c4228' sqlid='7dq8qm13md0cf'
SELECT :B1 - 10 FROM DUAL
END OF STMT
PARSE #2:c=0,e=309,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=1,plh=1388734953,tim=1302411557311362
BINDS #2:
Bind#0
oacdty=12 mxl=07(07) mxlc=00 mal=00 scl=00 pre=00
oacflg=13 fl2=206001 frm=00 csi=00 siz=8 off=0
kxsbbbfp=006a49a8 bln=07 avl=07 flg=09
value="8/13/2009 23:35:45"
EXEC #2:c=0,e=554,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=1,plh=1388734953,tim=1302411557312312
FETCH #2:c=1000,e=369,p=0,cr=0,cu=0,mis=0,r=1,dep=1,og=1,plh=1388734953,tim=1302411557312847
STAT #2 id=1 cnt=1 pid=0 pos=1 obj=0 op='FAST DUAL (cr=0 pr=0 pw=0 time=0 us cost=2 size=0 card=1)'
CLOSE #2:c=0,e=32,dep=1,type=3,tim=1302411557313358
=====================
PARSING IN CURSOR #2 len=25 dep=1 uid=184 oct=3 lid=184 tim=1302411557314018 hv=1194754446 ad='2d7c4228' sqlid='7dq8qm13md0cf'
SELECT :B1 - 10 FROM DUAL
END OF STMT
BINDS #2:
Bind#0
oacdty=12 mxl=07(07) mxlc=00 mal=00 scl=00 pre=00
oacflg=13 fl2=206001 frm=00 csi=00 siz=8 off=0
kxsbbbfp=006a49a8 bln=07 avl=07 flg=09
value="7/6/2010 14:28:11"
EXEC #2:c=0,e=467,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=1,plh=1388734953,tim=1302411557314344
FETCH #2:c=0,e=223,p=0,cr=0,cu=0,mis=0,r=1,dep=1,og=1,plh=1388734953,tim=1302411557314745
CLOSE #2:c=0,e=9,dep=1,type=3,tim=1302411557314880
=====================
PARSING IN CURSOR #2 len=25 dep=1 uid=184 oct=3 lid=184 tim=1302411557315047 hv=1194754446 ad='2d7c4228' sqlid='7dq8qm13md0cf'
SELECT :B1 - 10 FROM DUAL
END OF STMT
BINDS #2:
Bind#0
oacdty=12 mxl=07(07) mxlc=00 mal=00 scl=00 pre=00
oacflg=13 fl2=206001 frm=00 csi=00 siz=8 off=0
kxsbbbfp=006a49a8 bln=07 avl=07 flg=09
value="10/14/2010 1:27:25"
EXEC #2:c=0,e=349,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=1,plh=1388734953,tim=1302411557315361
FETCH #2:c=0,e=35,p=0,cr=0,cu=0,mis=0,r=1,dep=1,og=1,plh=1388734953,tim=1302411557315478
CLOSE #2:c=0,e=13,dep=1,type=3,tim=1302411557315639
=====================
PARSING IN CURSOR #2 len=25 dep=1 uid=184 oct=3 lid=184 tim=1302411557315868 hv=1194754446 ad='2d7c4228' sqlid='7dq8qm13md0cf'
SELECT :B1 - 10 FROM DUAL
END OF STMT
BINDS #2:
Bind#0
oacdty=12 mxl=07(07) mxlc=00 mal=00 scl=00 pre=00
oacflg=13 fl2=206001 frm=00 csi=00 siz=8 off=0
kxsbbbfp=006a49a8 bln=07 avl=07 flg=09
value="10/14/2010 1:40:57"
EXEC #2:c=0,e=331,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=1,plh=1388734953,tim=1302411557316162
FETCH #2:c=0,e=132,p=0,cr=0,cu=0,mis=0,r=1,dep=1,og=1,plh=1388734953,tim=1302411557316371
CLOSE #2:c=0,e=8,dep=1,type=3,tim=1302411557316486
=====================
PARSING IN CURSOR #2 len=25 dep=1 uid=184 oct=3 lid=184 tim=1302411557316780 hv=1194754446 ad='2d7c4228' sqlid='7dq8qm13md0cf'
SELECT :B1 - 10 FROM DUAL
END OF STMT
BINDS #2:
Bind#0
oacdty=12 mxl=07(07) mxlc=00 mal=00 scl=00 pre=00
oacflg=13 fl2=206001 frm=00 csi=00 siz=8 off=0
kxsbbbfp=006a49a8 bln=07 avl=07 flg=09
value="10/14/2010 2:18:35"
EXEC #2:c=0,e=360,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=1,plh=1388734953,tim=1302411557317077
FETCH #2:c=0,e=37,p=0,cr=0,cu=0,mis=0,r=1,dep=1,og=1,plh=1388734953,tim=1302411557317208
CLOSE #2:c=0,e=7,dep=1,type=3,tim=1302411557317284
=====================
PARSING IN CURSOR #2 len=25 dep=1 uid=184 oct=3 lid=184 tim=1302411557317405 hv=1194754446 ad='2d7c4228' sqlid='7dq8qm13md0cf'
SELECT :B1 - 10 FROM DUAL
END OF STMT
BINDS #2:
Bind#0
oacdty=12 mxl=07(07) mxlc=00 mal=00 scl=00 pre=00
oacflg=13 fl2=206001 frm=00 csi=00 siz=8 off=0
kxsbbbfp=006a49a8 bln=07 avl=07 flg=09
value="2/5/2011 8:4:52"
EXEC #2:c=1999,e=1239,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=1,plh=1388734953,tim=1302411557318621
FETCH #2:c=0,e=229,p=0,cr=0,cu=0,mis=0,r=1,dep=1,og=1,plh=1388734953,tim=1302411557318947
CLOSE #2:c=0,e=8,dep=1,type=3,tim=1302411557319086
=====================
PARSING IN CURSOR #2 len=25 dep=1 uid=184 oct=3 lid=184 tim=1302411557319365 hv=1194754446 ad='2d7c4228' sqlid='7dq8qm13md0cf'
SELECT :B1 - 10 FROM DUAL
END OF STMT
BINDS #2:
Bind#0
oacdty=12 mxl=07(07) mxlc=00 mal=00 scl=00 pre=00
oacflg=13 fl2=206001 frm=00 csi=00 siz=8 off=0
kxsbbbfp=006a49a8 bln=07 avl=07 flg=09
value="2/5/2011 8:18:5"
EXEC #2:c=1000,e=323,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=1,plh=1388734953,tim=1302411557319637
FETCH #2:c=0,e=216,p=0,cr=0,cu=0,mis=0,r=1,dep=1,og=1,plh=1388734953,tim=1302411557320053
CLOSE #2:c=0,e=31,dep=1,type=3,tim=1302411557320250
=====================
PARSING IN CURSOR #2 len=25 dep=1 uid=184 oct=3 lid=184 tim=1302411557321372 hv=1194754446 ad='2d7c4228' sqlid='7dq8qm13md0cf'
SELECT :B1 - 10 FROM DUAL
END OF STMT
BINDS #2:
Bind#0
oacdty=12 mxl=07(07) mxlc=00 mal=00 scl=00 pre=00
oacflg=13 fl2=206001 frm=00 csi=00 siz=8 off=0
kxsbbbfp=006a49a8 bln=07 avl=07 flg=09
value="4/5/2011 7:43:23"
EXEC #2:c=1000,e=479,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=1,plh=1388734953,tim=1302411557321641
FETCH #2:c=0,e=233,p=0,cr=0,cu=0,mis=0,r=1,dep=1,og=1,plh=1388734953,tim=1302411557322107
CLOSE #2:c=0,e=32,dep=1,type=3,tim=1302411557322321
=====================
PARSING IN CURSOR #2 len=25 dep=1 uid=184 oct=3 lid=184 tim=1302411557323024 hv=1194754446 ad='2d7c4228' sqlid='7dq8qm13md0cf'
SELECT :B1 - 10 FROM DUAL
END OF STMT
BINDS #2:
Bind#0
oacdty=12 mxl=07(07) mxlc=00 mal=00 scl=00 pre=00
oacflg=13 fl2=206001 frm=00 csi=00 siz=8 off=0
kxsbbbfp=006a49a8 bln=07 avl=07 flg=09
value="4/9/2011 21:28:1"
EXEC #2:c=0,e=264,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=1,plh=1388734953,tim=1302411557323236
FETCH #2:c=0,e=145,p=0,cr=0,cu=0,mis=0,r=1,dep=1,og=1,plh=1388734953,tim=1302411557323463
CLOSE #2:c=0,e=79,dep=1,type=3,tim=1302411557323718
=====================
PARSING IN CURSOR #2 len=25 dep=1 uid=184 oct=3 lid=184 tim=1302411557323946 hv=1194754446 ad='2d7c4228' sqlid='7dq8qm13md0cf'
SELECT :B1 - 10 FROM DUAL
END OF STMT
BINDS #2:
Bind#0
oacdty=12 mxl=07(07) mxlc=00 mal=00 scl=00 pre=00
oacflg=13 fl2=206001 frm=00 csi=00 siz=8 off=0
kxsbbbfp=006a49a8 bln=07 avl=07 flg=09
value="4/9/2011 8:39:13"
EXEC #2:c=0,e=209,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=1,plh=1388734953,tim=1302411557324117
FETCH #2:c=0,e=35,p=0,cr=0,cu=0,mis=0,r=1,dep=1,og=1,plh=1388734953,tim=1302411557324221
CLOSE #2:c=0,e=38,dep=1,type=3,tim=1302411557324259
=====================
PARSING IN CURSOR #2 len=25 dep=1 uid=184 oct=3 lid=184 tim=1302411557324448 hv=1194754446 ad='2d7c4228' sqlid='7dq8qm13md0cf'
SELECT :B1 - 10 FROM DUAL
END OF STMT
BINDS #2:
Bind#0
oacdty=12 mxl=07(07) mxlc=00 mal=00 scl=00 pre=00
oacflg=13 fl2=206001 frm=00 csi=00 siz=8 off=0
kxsbbbfp=006a49a8 bln=07 avl=07 flg=09
value="4/9/2011 8:12:42"
EXEC #2:c=1000,e=305,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=1,plh=1388734953,tim=1302411557324717
FETCH #2:c=0,e=45,p=0,cr=0,cu=0,mis=0,r=1,dep=1,og=1,plh=1388734953,tim=1302411557325018
CLOSE #2:c=0,e=8,dep=1,type=3,tim=1302411557325106
=====================
PARSING IN CURSOR #2 len=25 dep=1 uid=184 oct=3 lid=184 tim=1302411557325243 hv=1194754446 ad='2d7c4228' sqlid='7dq8qm13md0cf'
SELECT :B1 - 10 FROM DUAL
END OF STMT
BINDS #2:
Bind#0
oacdty=12 mxl=07(07) mxlc=00 mal=00 scl=00 pre=00
oacflg=13 fl2=206001 frm=00 csi=00 siz=8 off=0
kxsbbbfp=006a49a8 bln=07 avl=07 flg=09
value="4/9/2011 21:58:17"
EXEC #2:c=0,e=201,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=1,plh=1388734953,tim=1302411557325415
FETCH #2:c=0,e=28,p=0,cr=0,cu=0,mis=0,r=1,dep=1,og=1,plh=1388734953,tim=1302411557325493
CLOSE #2:c=0,e=149,dep=1,type=3,tim=1302411557334524
.
.
.
No comments:
Post a Comment