Oracle FAQ Your Portal to the Oracle Knowledge Grid
HOME | ASK QUESTION | ADD INFO | SEARCH | E-MAIL US
 

Home -> Community -> Usenet -> c.d.o.server -> Inconsistency in 10046 trace result with 'ela=' value ?

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

From: Sébastien de Mapias <sglrigaud_at_gmail.com>
Date: 24 Apr 2007 05:28:46 -0700
Message-ID: <1177417726.490829.120990@t39g2000prd.googlegroups.com>


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 Received on Tue Apr 24 2007 - 07:28:46 CDT

Original text of this message

HOME | ASK QUESTION | ADD INFO | SEARCH | E-MAIL US