Re: TKPROF: Long CPU time on Execute

From: dx <seaelephant_at_hotmail.com>
Date: 20 Apr 2004 11:18:40 -0700
Message-ID: <7f28ac37.0404201018.610e486c@posting.google.com>

rgaffuri_at_cox.net (Ryan Gaffuri) wrote in message news:<1efdad5b.0404200341.21f6aad9_at_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?

Look at the 'c'(cpu time) and 'e'(elapsed) time, for EXEC #3 line, cpu time is 0, and elapsed time is 0.000197s, but for the first FETCH #3 line, cpu time is 0.55s and elapsed time is 14.19s, the WAIT events ( write and read temp segment due to sort ) before the first FETCH contribute to the 14.19s elapsed time.

> >
> > >
> > > 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 - 13:18:40 CDT