Re: High elapsed/cpu ratio

"R.Wang" <R.Wang_at_oraclepoint.com> wrote in message news:1189482809.926373.101520_at_r34g2000hsd.googlegroups.com...
> On Sep 10, 11:07 am, ebwri..._at_gmail.com wrote:
>> I'm working on tuning a particular query and have gotten the explain
>> plan as pretty as possible, low cost, etc. However, when running the
>> query (an insert into table select ... statement), I find the
>> following information in the tkprof trace file:
>>
>> call count cpu elapsed disk query
>> current rows
>> ------- ------ -------- ---------- ---------- ---------- ----------
>> ----------
>> Parse 1 0.02 0.02 0 0
>> 0 0
>> Execute 1 170.59 2289.34 870183 16953935
>> 49 5
>> Fetch 0 0.00 0.00 0 0
>> 0 0
>> ------- ------ -------- ---------- ---------- ---------- ----------
>> ----------
>> total 2 170.61 2289.37 870183 16953935
>> 49 5
>>
>> The cpu spent less than 3m executing the query, but it took nearly 40m
>> for results to be retrieved and inserted. This was done in a
>> development environment with little to no other users (so, no locking
>> issues), fresh statistics on tables and indexes, and an empty target
>> table that was truncated immediately before processing.
>>
>> The one issue I know that could cause problems is that the tables
>> being accessed are in a very large (~500 GB) tablespace. This is not
>> something that can be changed at this time.
>>
>> Thanks,
>> Eric
>
> Hi Eric,
>
> 1.The hit ratio is Good.
>
> Logical Reads = query + current
> Logical Reads = 16953935+0 + 49+0
> Logical Reads = 16953935 + 49
> Logical Reads = 16953984
>
> Hit Ratio = 1 - (Physical Reads / Logical Reads)
> Hit Ratio = 1 - ((870183+0) / 16953984)
> Hit Ratio = 1 - (0.05)
> Hit Ratio = 95%
>
> Go follow other postings to trace event 10046.
>

Hi R.Wang

The problem with hit ratios of course is that even 5% of a real real lot can still equal a lot.

Here we have 16,953,984 LIOs (which might well be considered a real real lot) of which we still have 870,183 PIOs (which might well be considered to still be a lot).

Perhaps, just perhaps, a fair proportion of the "unexplained" elapsed time might just be explained by the fact we have nearly 1 million PIOs happening here. That works out to be roughly 380 PIOs per sec which isn't too bad (3ms average per I/O).

Now, absolutely look at the raw trace file and investigate the actual wait events but not because of yet another poor example of using a hit ratio ...

It also seems to be an awful lot of work just to insert 5 rows into a table, hope there's some aggregation happening ;)

Cheers

Richard Received on Tue Sep 11 2007 - 07:08:20 CDT