Re: High elapsed/cpu ratio

On Sep 11, 9:38 am, "Richard Foote" <richard.fo..._at_nospam.bigpond.com> wrote:
> "Alberto Frosi" <alberto.fr..._at_gmail.com> wrote in message
>
> news:1189515886.196731.106620_at_r34g2000hsd.googlegroups.com...
>
>
>
> > On 11 Set, 14:08, "Richard Foote" <richard.fo..._at_nospam.bigpond.com>
> > wrote:
> >> "R.Wang" <R.W..._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
>
> > Hi Richard,
> > Great answer, but in this case there aren't system performance
> > problems but the real problem it's the insert query then.
> > we must to analyze a trace file for know the real problem, isn't it?
>
> Hi Alberto
>
> The insert query is performing 16 Million I/Os.
>
> Explain the query, examine the execution plan and determine why the thing is
> so expensive.
>
> Cheers
>
> Richard

I agree with this. It boggles my mind that you would have to join two multi-million tables to insert five rows? Maybe something is wrong with the application (LOL! I supported Oracle Apps for six years, so I *know* that is true :)) Up until the most recent release, their application software still *required* 8.0.6 client side software.

Regards,

Steve Received on Tue Sep 11 2007 - 10:24:22 CDT