Oracle FAQ Your Portal to the Oracle Knowledge Grid
HOME | ASK QUESTION | ADD INFO | SEARCH | E-MAIL US
 

Home -> Community -> Usenet -> c.d.o.server -> Re: TKPROF: Long CPU time on Execute

Re: TKPROF: Long CPU time on Execute

From: dx <seaelephant_at_hotmail.com>
Date: 19 Apr 2004 11:11:10 -0700
Message-ID: <7f28ac37.0404191011.41f5316c@posting.google.com>


pkolton_at_hotmail.com (Pete) wrote in message news:<ed168c92.0404161529.4c02d2be_at_posting.google.com>...
> Fair enough; ORDER BY, GROUP BY would count during execute. But that
> isn't happening here.

ORDER BY, GROUP BY would count during *fetch*. Sybrand is wrong. You can easily find this in raw trace file, for instance,

PARSING IN CURSOR #3 len=36 dep=1 uid=70 oct=3 lid=70 tim=6987540761221 hv=1233230066 ad='22af0758' SELECT * from t order by object_name
END OF STMT
PARSE #3:c=0,e=9014,p=0,cr=2,cu=0,mis=1,r=0,dep=1,og=4,tim=6987540761201 BINDS #3:

EXEC #3:c=0,e=197,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,tim=6987540761724
WAIT #3: nam='direct path write' ela= 574211 p1=201 p2=104201 p3=7
WAIT #3: nam='direct path write' ela= 284665 p1=201 p2=104215 p3=7
...
WAIT #3: nam='direct path read' ela= 754 p1=201 p2=104201 p3=7
FETCH #3:c=550000,e=14189986,p=42,cr=332,cu=4,mis=0,r=1,dep=1,og=4,tim=6987554952004
FETCH #3:c=0,e=43,p=0,cr=0,cu=0,mis=0,r=1,dep=1,og=4,tim=6987554952417
FETCH #3:c=0,e=38,p=0,cr=0,cu=0,mis=0,r=1,dep=1,og=4,tim=6987554952662
FETCH #3:c=0,e=73,p=0,cr=0,cu=0,mis=0,r=1,dep=1,og=4,tim=6987554953190

Look at the EXEC line and the first FETCH line.

>
> I have an example of a trace of the same statement on another database
> (same execution plan) where the statement is executed 16753 times. In
> this case the CPU time for the fetch is slightly more at 1.42 seconds,
> but the CPU time for the execute is only 1.28 seconds, as opposed to
> the 1484 (nearly 25 minutes) seconds in the first example.
>
> I have tried opening, fetching, and closing this cursor on a copy of
> the database (the high CPU example is from a client's database) 8700
> times and it took 6.8 seconds after flushing the SGA, and then about
> 0.6 seconds on subsequent executions.
>
> As I said in the original post, this statement was a simple example
> from the trace file, but others in there also have very high CPU times
> on the execute phase (e.g. 8845 seconds for 8453 executes; that's
> nearly 2.5 hours! - but only 20 seconds for 17154 fetches). Again
> this is for a statement with no ORDER BY, GROUP BY etc.
>
>

This is a very interesting problem, would you mind posting the raw event trace file with level 12 ( only the beginning of the file and the piece of targeted cursor operation )?

Thanks,
DX

> Sybrand Bakker <gooiditweg_at_sybrandb.verwijderdit.demon.nl> wrote in message news:<ir40805l80nli57f2uhdfcn8tm52a7bgnv_at_4ax.com>...
>
> >
> > That 1484 seconds for a statement which is called 8701 times, and 1.33
> > seconds for 8701 fetches returning 0 rows.
> > Doesn't look like unreasonable to me.
> >
> > Also: you are wrong in assuming only INSERT and UPDATE consume CPU
> > during the execute phase. ORDER BY, GROUP BY and the like are executed
> > on in the database, so they also count during execute. A range scan,
> > as you can see counts during execute.
Received on Mon Apr 19 2004 - 13:11:10 CDT

Original text of this message

HOME | ASK QUESTION | ADD INFO | SEARCH | E-MAIL US