Re: Question about TKPROF output.
Date: Wed, 21 May 2008 12:36:31 -0700 (PDT)
Message-ID: <48868.45601.qm@web80602.mail.mud.yahoo.com>
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_at_lagan.com>
> Date: Tue, 20 May 2008 13:21:23 +0100
> Subject: Question about TKPROF output.
>
> All,
>
> I would just like some clarification on a point:
>> rows
> call count cpu elapsed disk query current
> ------- ------ -------- ---------- ---------- ---------- ----------
> ----------
> 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
-- http://www.freelists.org/webpage/oracle-lReceived on Wed May 21 2008 - 14:36:31 CDT