If i execute the following pl/sql block, which loops 100 times. Each time flushing the buffer cache (to force physical reads) and then forcing a FTS of the table. Hopefully I will see any intermittent WAIT issues.
declare
n number;
begin
for i in 1..100 loop
execute immediate 'ALTER SYSTEM FLUSH BUFFER_CACHE';
select /*+ FULL(T) */ count(*)
into n
from timtab T;
end loop;
end;
/
Now if i tkprof the trace file using SORT=FCHELA, and look under the 'Elapsed times include...events' section for this statement. I can see max wait for each wait event. So at one point the database waited 30.47 for one 'db file scattered read'.
SQL ID: a6dnnq27u3u3q Plan Hash: 3724264953
SELECT /*+ FULL(T) */ COUNT(*)
FROM
timtab T
call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 1 0.00 0.00 2 2 0 0
Execute 10 0.00 0.00 0 0 0 0
Fetch 10 5.53 112.14 401421 402050 0 10
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 21 5.53 112.14 401423 402052 0 10
Misses in library cache during parse: 1
Optimizer mode: ALL_ROWS
Parsing user id: 97 (recursive depth: 1)
Number of plan statistics captured: 1
Rows (1st) Rows (avg) Rows (max) Row Source Operation
---------- ---------- ---------- ---------------------------------------------------
1 1 1 SORT AGGREGATE (cr=40205 pr=39702 pw=0 time=33791600 us)
1000000 1000000 1000000 TABLE ACCESS FULL T1 (cr=40205 pr=39702 pw=0 time=485535 us cost=11036 size=0 card=1049724)
Elapsed times include waiting on following events:
Event waited on Times Max. Wait Total Waited
---------------------------------------- Waited ---------- ------------
db file scattered read 3367 30.47 107.07
db file sequential read 28 0.00 0.01
I can confirm this by looking at the actual trace file. Looking at the second last line, I can see a particular 'db file scattered read' waited for ela= 30441786 micro seconds (30 seconds).
=====================
PARSING IN CURSOR #140011222423880 len=41 dep=1 uid=97 oct=3 lid=97 tim=1404231570216055 hv=2409752694 ad='65b88adb8' sqlid='a6dnnq27u3u3q'
SELECT /*+ FULL(T) */ COUNT(*) FROM timtab T
END OF STMT
PARSE #140011222423880:c=29996,e=388998,p=743,cr=331,cu=1,mis=1,r=0,dep=1,og=1,plh=3724264953,tim=1404231570216054
EXEC #140011222423880:c=0,e=31,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=1,plh=3724264953,tim=1404231570216131
WAIT #140011222423880: nam='db file scattered read' ela= 4239 file#=4 block#=1019 blocks=5 obj#=91752 tim=1404231570220492
WAIT #140011222423880: nam='db file scattered read' ela= 16142 file#=4 block#=1032 blocks=8 obj#=91752 tim=1404231570236824
WAIT #140011222423880: nam='db file scattered read' ela= 1462 file#=4 block#=1041 blocks=7 obj#=91752 tim=1404231570238476
WAIT #140011222423880: nam='db file scattered read' ela= 8129 file#=4 block#=1048 blocks=8 obj#=91752 tim=1404231570246799
...
*** 2014-07-01 16:20:02.556
WAIT #140011222423880: nam='db file scattered read' ela= 30441786 file#=4 block#=26008 blocks=128 obj#=91752 tim=1404231602556217
WAIT #140011222423880: nam='db file scattered read' ela= 3436 file#=4 block#=26136 blocks=112 obj#=91752 tim=1404231602562084
Thanks goes to Mr Niall Litchfield.
******************************************
keywords: trace
******************************************
rdbms version: 11g
******************************************
No comments:
Post a Comment