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: Ryan Gaffuri <rgaffuri_at_cox.net>
Date: 20 Apr 2004 04:41:16 -0700
Message-ID: <1efdad5b.0404200341.21f6aad9@posting.google.com>


seaelephant_at_hotmail.com (dx) wrote in message news:<7f28ac37.0404191011.41f5316c_at_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.

what am I supposed to look for? The 'tim' field stands out in fetch and execute how does that tell me that the order by costs against the fetch phase?
>
> >
> > 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 Tue Apr 20 2004 - 06:41:16 CDT

Original text of this message

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