Re: TKPROF: Long CPU time on Execute

Given the high CPU time in the Execute line, but complete absence of logical I/O, I'd guess that this system using a held cursor in a way that is causing optimisation to take place on the execute rather than the parse.

You won't see any library cache misses recorded in the trace or tkprof output for this - it's only in 10g (I think) that you get lines like:

    Misses in library cache during parse: NN

Of course, you then need to find out why you are re-optimising so often. A little background to how the code arrives would help. And you could check v$sql and v$sql_shared_cursor to see if they give you any clues. (how many child cursors are there for this SQL, and are there any flagged reasons why Oracle couldn't share).

Regards

Jonathan Lewis
http://www.jlcomp.demon.co.uk

The Co-operative Oracle Users' FAQ
http://www.jlcomp.demon.co.uk/faq/ind_faq.html

April 2004 Iceland http://www.index.is/oracleday.php June 2004 UK - Optimising Oracle Seminar July 2004 USA West Coast, Optimising Oracle Seminar August 2004 Charlotte NC, Optimising Oracle Seminar September 2004 USA East Coast, Optimising Oracle Seminar September2004 UK - Optimising Oracle Seminar

"Pete" <pkolton_at_hotmail.com> wrote in message news:ed168c92.0404160820.7b66201_at_posting.google.com...
> I've got the following results from a trace. The SELECT statement
> I've posted here wasn't the worst performing, but it is the simplest
> SELECT in the file, and it's still pretty bad!
>
> What is puzzling me is the very high CPU and Elapsed time on Execute.
> Massively higher than on the Fetch. I know that an elapsed time that
> is much longer than the CPU time indicates that the session was
> waiting for something, but that isn't the case here.
>
> As you can see; 1.33 seconds CPU on the Fetch, but 1484 seconds on the
> Execute! I thought that it was only Inserts and Updates that did a
> lot of work on the Execute?
>
>
> SELECT *
> FROM
> XXX_CALENDAR WHERE CALENDAR_DATE = :b1 AND CALENDAR_TYPE = 'P' AND
> STATE_CODE = :b2
>
>
> call count cpu elapsed disk query current
> rows
> ------- ------ -------- ---------- ---------- ---------- ----------
> ----------
> Parse 0 0.00 0.00 0 0 0
> 0
> Execute 8701 1484.77 1955.71 0 0 0
> 0
> Fetch 8701 1.33 1.24 0 26103 0
> 281
> ------- ------ -------- ---------- ---------- ---------- ----------
> ----------
> total 17402 1486.10 1956.95 0 26103 0
> 281
>
> Misses in library cache during parse: 0
> Optimizer goal: CHOOSE
> Parsing user id: 52 (QS) (recursive depth: 1)
>
Received on Mon Apr 19 2004 - 19:07:13 CDT