Re: Question about TKPROF output.
- From: Yong Huang <yong321@xxxxxxxxx>
- To: oracle-l@xxxxxxxxxxxxx
- Date: Wed, 21 May 2008 12:36:31 -0700 (PDT)
I thought it should include disk blocks accessed through direct path. But I
just did a test and the numbers don't quite add up. The database is 10.2.0.4
64-bit Linux. disk_asynch_io is default true and filesystemio_options is
default none if they matter.
alter session set workarea_size_policy=manual;
alter session set sort_area_size=1;
alter session set hash_area_size = 1;
--explain plan for select /*+ use_hash(a) */ count(*) from ow a, big b where
a.i = b.line;
--Make sure TempSpc column is shown: @?/rdbms/admin/utlxpls
alter session set tracefile_identifier = hashtest;
alter session set events '10046 trace name context forever, level 8';
select /*+ use_hash(a) */ count(*) from ow a, big b where a.i = b.line;
alter session set events '10046 trace name context off';
The tkprof'ed trace file shows:
select /*+ use_hash(a) */ count(*)
from
ow a, big b where a.i = b.line
call count cpu elapsed disk query current
rows
------- ------ -------- ---------- ---------- ---------- ----------
----------
Parse 1 0.00 0.00 0 1 0
0
Execute 1 0.00 0.00 0 0 0
0
Fetch 2 9.00 27.49 43967 26638 0
1
------- ------ -------- ---------- ---------- ---------- ----------
----------
total 4 9.00 27.50 43967 26639 0
1
Misses in library cache during parse: 1
Optimizer mode: ALL_ROWS
Parsing user id: 599
Rows Row Source Operation
------- ---------------------------------------------------
1 SORT AGGREGATE (cr=26638 pr=43967 pw=2684 time=27491836 us)
2029417 HASH JOIN (cr=26638 pr=43967 pw=2684 time=26385795 us)
8734 INDEX FAST FULL SCAN OW_PK (cr=23 pr=20 pw=0 time=18608 us)(object
id 240097)
2031611 TABLE ACCESS FULL BIG (cr=26615 pr=26555 pw=0 time=6102931 us)
Elapsed times include waiting on following events:
Event waited on Times Max. Wait Total Waited
---------------------------------------- Waited ---------- ------------
SQL*Net message to client 2 0.00 0.00
db file sequential read 2 0.00 0.00
db file scattered read 1702 0.09 4.52
direct path write temp 2684 0.00 0.07
direct path read temp 17392 0.05 10.28
SQL*Net message from client 2 3.04 3.04
Sum the blocks accessed by direct path read and write:
$ awk '/direct path/{print $14}' ristss1t_ora_20738_HASHTEST.trc | awk -F=
'{a+=$2}END{print a}'
20081
Sum the blocks accessed by just direct path read:
$ awk '/direct path read/{print $14}' ristss1t_ora_20738_HASHTEST.trc | awk -F=
'{a+=$2}END{print a}'
17395
Sum the blocks accessed by db file scattered and sequential read:
$ awk '/db file s/{print $11}' ristss1t_ora_20738_HASHTEST.trc | awk -F=
'{a+=$2}END{print a}'
26641
Sum the number of times of direct path reads or writes:
$ grep -c 'direct path ' ristss1t_ora_20738_HASHTEST.trc
20081
Note that 43967 is not a sum of any of the numbers from the awk commands. The
closest is 17395+26641=44036, which is 69 higher.
By the way, I looked at this before but without direct path reads and writes,
and the numbers add up perfectly. See
http://yong321.freeshell.org/computer/diskreadunit.txt
Yong Huang
> From: Ronnie Doggart <ronnie_doggart@xxxxxxxxx>
> Date: Tue, 20 May 2008 13:21:23 +0100
> Subject: Question about TKPROF output.
>
> All,
>
> I would just like some clarification on a point:
>
> 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 20 1.01 10.85 6171 7395 0
> 283
> ------- ------ -------- ---------- ---------- ---------- ----------
> ----------
> total 22 1.01 10.85 6171 7395 0
> 283
>
> When the tkprof output shows disk activity of 6171 does this include blocks
> used in one/multi pass hash joins. Are the direct path reads/writes included
?
>
> Elapsed times include waiting on following events:
> Event waited on Times Max. Wait Total Waited
> ---------------------------------------- Waited ---------- ------------
> SQL*Net message to client 20 0.00 0.00
> db file sequential read 851 0.03 2.32
> db file scattered read 341 0.03 1.89
> direct path write 312 0.06 3.99
> direct path read 312 0.03 1.60
> SQL*Net message from client 20 2.27 35.33
>
********************************************************************************
>
> Ronnie Doggart
> Database Architect
> Lagan
> 209 Airport Road West
> Belfast
> BT3 9EZ
> Connecting Governments and People
> T: +44 (0) 28 9078 8300
> F: +44 (0) 28 9078 8339
> W: www.lagan.com
--
//www.freelists.org/webpage/oracle-l
Other related posts:
