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

SĂ©bastien de Mapias <sglrigaud_at_gmail.com> writes:

> 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

Hello Sebastien,
did you run your trace file through tkprof? I find the contents of the trace file too confusing to read it without the help of tkprof. Maybe the output of tkprof gives some hints to understand your issue.

Hope that helps,
Lothar Received on Tue Apr 24 2007 - 10:46:10 CDT