| Oracle FAQ | Your Portal to the Oracle Knowledge Grid | |
 |
 | |||
| Oracle FAQ | Your Portal to the Oracle Knowledge Grid | |
|
| |||
Home -> Community -> Usenet -> c.d.o.server -> Re: Buffer cache statistics (ratios) and CBO SQL optimization?
It just so happens that on my 9204 laptop that when run through tkprof shows
OVERALL TOTALS FOR ALL RECURSIVE STATEMENTS
call count cpu elapsed disk query current
rows
------- ------ -------- ---------- ---------- ---------- ---------- ------
Misses in library cache during parse: 164 Misses in library cache during execute: 1
Elapsed times include waiting on following events:
Event waited on Times Max. Wait TotalWaited
db file sequential read 160004 1.49 398.90 db file scattered read 20732 0.4386.62
suggesting an *average* physical IO time for a single block read of 3989000/160004=25 milliseconds.
the trace file itself also contains a representative fragment like
PARSING IN CURSOR #16 len=147 dep=1 uid=0 oct=3 lid=0 tim=1350909987
hv=1356713530 ad='502ee500'
select privilege#,level from sysauth$ connect by grantee#=prior privilege#
and privilege#>0 start with (grantee#=:1 or grantee#=1) and privilege#>0
END OF STMT
PARSE #16:c=15625,e=4166,p=0,cr=22,cu=0,mis=1,r=0,dep=1,og=0,tim=1350909981
BINDS #16:
bind 0: dty=2 mxl=22(22) mal=00 scl=00 pre=00 oacflg=08 oacfl2=1 size=24
offset=0
bfp=0946a30c bln=22 avl=02 flg=05
value=43
EXEC #16:c=0,e=657,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,tim=1350910784
FETCH #16:c=0,e=744,p=0,cr=28,cu=0,mis=0,r=1,dep=1,og=4,tim=1350911573 FETCH #16:c=0,e=15,p=0,cr=0,cu=0,mis=0,r=1,dep=1,og=4,tim=1350911628 FETCH #16:c=0,e=10,p=0,cr=0,cu=0,mis=0,r=1,dep=1,og=4,tim=1350911667 FETCH #16:c=0,e=9,p=0,cr=0,cu=0,mis=0,r=1,dep=1,og=4,tim=1350911705 FETCH #16:c=0,e=10,p=0,cr=0,cu=0,mis=0,r=1,dep=1,og=4,tim=1350911743 FETCH #16:c=0,e=9,p=0,cr=0,cu=0,mis=0,r=1,dep=1,og=4,tim=1350911781 FETCH #16:c=0,e=9,p=0,cr=0,cu=0,mis=0,r=1,dep=1,og=4,tim=1350911819 FETCH #16:c=0,e=9,p=0,cr=0,cu=0,mis=0,r=1,dep=1,og=4,tim=1350911857 FETCH #16:c=0,e=9,p=0,cr=0,cu=0,mis=0,r=1,dep=1,og=4,tim=1350911894 FETCH #16:c=0,e=8,p=0,cr=0,cu=0,mis=0,r=1,dep=1,og=4,tim=1350911931 FETCH #16:c=0,e=10,p=0,cr=0,cu=0,mis=0,r=1,dep=1,og=4,tim=1350911970 FETCH #16:c=0,e=8,p=0,cr=0,cu=0,mis=0,r=1,dep=1,og=4,tim=1350912007 FETCH #16:c=0,e=52,p=0,cr=0,cu=0,mis=0,r=1,dep=1,og=4,tim=1350912088 FETCH #16:c=0,e=9,p=0,cr=0,cu=0,mis=0,r=1,dep=1,og=4,tim=1350912127 FETCH #16:c=0,e=9,p=0,cr=0,cu=0,mis=0,r=1,dep=1,og=4,tim=1350912164 FETCH #16:c=0,e=9,p=0,cr=0,cu=0,mis=0,r=1,dep=1,og=4,tim=1350912202 FETCH #16:c=0,e=8,p=0,cr=0,cu=0,mis=0,r=1,dep=1,og=4,tim=1350912239 FETCH #16:c=0,e=10,p=0,cr=0,cu=0,mis=0,r=1,dep=1,og=4,tim=1350912278 FETCH #16:c=0,e=9,p=0,cr=0,cu=0,mis=0,r=1,dep=1,og=4,tim=1350912316 FETCH #16:c=0,e=9,p=0,cr=0,cu=0,mis=0,r=1,dep=1,og=4,tim=1350912354 FETCH #16:c=0,e=9,p=0,cr=0,cu=0,mis=0,r=1,dep=1,og=4,tim=1350912392 FETCH #16:c=0,e=8,p=0,cr=0,cu=0,mis=0,r=1,dep=1,og=4,tim=1350912429 FETCH #16:c=0,e=12,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,tim=1350912470STAT #16 id=1 cnt=22 pid=0 pos=1 obj=0 op='CONNECT BY WITH FILTERING (cr=28 r=0 w=0 time=892 us)'
STAT #16 id=4 cnt=0 pid=3 pos=1 obj=110 op='INDEX RANGE SCAN I_SYSAUTH1
(cr=2 r=0 w=0 time=33 us)'
STAT #16 id=5 cnt=2 pid=3 pos=2 obj=110 op='INDEX RANGE SCAN I_SYSAUTH1
Now my reading of this which may well be incorrect is that the elapsed times for the fetches (which will be single block LIOs in this particular example) are about 10-20 microseconds. so it looks to me and on this system (1400mhz processor , RAID5 disk array) the difference is in the 1000-2000 times range.
comments and clarifications welcome. The LIO figure seems reasonable to me and not wildly out of line with Jonathan's conjecture, the disk figure seems about twice as big as I would expect :(. None of this appears to bear out my 10-100 times figure, nor does it bear out the 14000 times figures I have also seen.
-- Niall Litchfield Oracle DBA Audit Commission UKReceived on Tue Dec 30 2003 - 06:47:41 CST
 |
 |