Re: tkprof elapsed time
- From: "Vlad Sadilovskiy" <vlovsky@xxxxxxxxx>
- To: ax.mount@xxxxxxxxx
- Date: Wed, 21 Nov 2007 11:02:01 -0500
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@xxxxxxxxx> 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.72 for
> 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
>
>
Other related posts:
