Re: tkprof elapsed time

Alex,

This insert statement should not produce any "*log file sync*" waits. This is the *commit's* job :). SQL*Plus autocommit does not create a "commit" statement as such. The "action" for this "commit" would not have associated cursor slot. That's what I call "*call-less*" cursor. However, it would cause waits to occur with the #0 cursor or in come cases the slot number of a call that would has just been completed. Tkprof usually associates these waits with the call that follows.

Try reproducing it by issuing "COMMIT" explicitly. Regards,

Vlad Sadilovskiy
Oracle Database Tools
Web site: http://www.fourthelephant.com
Blog: http://vsadilovskiy.wordpress.com

On 11/21/07, amonte <ax.mount_at_gmail.com> wrote:
>
> Hi Vlad
>
> I dint have the trace file handy but it is very easy to reproduce.
>
> Generate 10000 insert statement to EMP Tabe and set autocommit on in
> sqlplus
>
> Thanks
>
> alex
>
> On Nov 21, 2007 5:02 PM, Vlad Sadilovskiy <vlovsky_at_gmail.com> wrote:
>
> > Amonte, it supposed to be calculated as you suggested with few
> > exceptions. Do you have cursors in the trace that end up at level higher
> > than zero followed by SQL*Net... waits? There could be some other problem
> > with it.
> >
> > Do you mind sending out the trace I'll "dig" into it :)
> >
> > Checkout this two articles that have example of strange behavior.
> >
> > BLOB write size and CPU<http://vsadilovskiy.wordpress.com/2007/11/19/blob-write-size-and-cpu/>
> > <http://vsadilovskiy.wordpress.com/2007/11/19/blob-write-size-and-cpu/>
> > Call-Less Cursor<http://vsadilovskiy.wordpress.com/2007/10/29/trace-and-statspack-lob-1/>
> >
> > Vlad Sadilovskiy
> > Oracle Database Tools
> > Web site: http://www.fourthelephant.com
> > Blog: http://vsadilovskiy.wordpress.com
> >
> > On 11/21/07, amonte <ax.mount_at_gmail.com> wrote:
> > >
> > > Hi
> > >
> > > In a TKPROF output such as follows:
> > >
> > > call count cpu elapsed disk query
> > > current rows
> > > ------- ------ -------- ---------- ---------- ---------- ----------
> > > ----------
> > > Parse 1 0.00 0.00 0 0
> > > 0 0
> > > Execute 7045 8.68 8.72 0 156
> > > 159502 7045
> > > Fetch 0 0.00 0.00 0 0
> > > 0 0
> > > ------- ------ -------- ---------- ---------- ---------- ----------
> > > ----------
> > > total 7046 8.68 8.72 0 156
> > > 159502 7045
> > >
> > > Misses in library cache during parse: 0
> > > Optimizer mode: ALL_ROWS
> > > Parsing user id: 63
> > >
> > > Elapsed times include waiting on following events:
> > > Event waited on Times Max. Wait Total
> > > Waited
> > > ---------------------------------------- Waited ----------
> > > ------------
> > > log file sync 7045 0.04
> > > 33.33
> > > SQL*Net message to client 7045 0.00
> > > 0.00
> > > SQL*Net message from client 7045 0.04
> > > 4.66
> > > log file switch completion 2 0.09
> > > 0.16
> > >
> > > Is elapsed time = cpu time + waits? Because in this case we have 8.72for elapsed time and
> > > 8.68 for cpu, log file sync waits is 33 seconds so shouldnt elapsed be
> > > around 42 seconds?
> > >
> > > Or the elapsed time is calculated in a different way :-?
> > >
> > > Alex
> > >
> > >
> >
> >
>
>

--
http://www.freelists.org/webpage/oracle-l