Re: Inconsistency in 10046 trace result with 'ela=' value ?

Sébastien de Mapias schrieb:
> Hi,
> I've just traced an insert that annoys us (takes about 6 minutes);
> then I edited the trc file, isolated the lines related to the INSERT
> statement and kept only the values of the 'ela=' variable in a small
> file called 'elaVals', and quickly did the following in ksh:
>
> integer j=0
> cat elaVals | while read fig;do
> let j=$fig+$j
> echo "ela=$fig, total=$j"
> done>result
>
> At the end of my 'result' file I get
> ....
> ela=20, total=5329048
> ela=23, total=5329071
> so apart from all the rest in my trace file the insert itself took a
> bit
> more than 5 seconds OK ? (see Metalink note 352184.1)
>
> 1/ how come that my trace file shows a duration of a few seconds
> when I know my insert lasts about 6 minutes really (the rest of
> the trc file contents -recursive sql- is negligible) ???
> 2/ now if I use the 'tim=' values to compute the duration of the
> execution I get totally unconsistent results with those previously
> calculated with 'ela=' (18 seconds):
> # > head -1 elaVals
> WAIT #26: nam='SQL*Net message to dblink' ela= 8 driver id=1413697536
> #bytes=1 p3=0 obj#=-1 tim=3366162081889
> # > tail -1 elaVals
> WAIT #26: nam='SQL*Net more data from dblink' ela= 23 driver
> id=1413697536 #bytes=37 p3=0 obj#=73496 tim=3366180179725
> # > echo $((3366180179725-3366162081889))
> 18097836
> Where does this difference (5.3 seconds on one side, 18 seconds on the
> other) come from ? When you sum up 'ela=' values shoudn't it amount
> to the difference between the last timer values and the first one ?
>
> Thanks.
> SR
>

Recursive sql may be not negligible, the ela times all contribute to the   whole wait time, so you have to sum them as well if there is some recursive sql (all waits related to "PARSING IN CURSOR..." with dep higher than dep of your INSERT cursor and occuring before INSERT in trace file and after any other with same or lower dep as your INSERT).

Difference between two tim lines and sum(ela) may be due to some reasons (for example due to uninstrumented kernel code) - it is perfectly well explained by Cary Milsap.

Perhaps, you can get more clear picture of your trace file if you would use one of available profiler - the one from Egor Starostin, orasrp is pretty good and has no cost.

Best regards

Maxim Received on Tue Apr 24 2007 - 12:33:25 CDT