Message
Stefan,
Thanks
for the reply. I don't think this is correct, however. My understanding of
forward attribution is that it isn't a definitive rule as much as a logical
outcome of the order in which work needs to be done. Let me explain. If I/O
needs to be done (scattered read, sequential read) to get some data, this needs
to be done prior to the FETCH. (you can't fetch the data if you haven't read it
into the SGA) In this case, the I/O waits precede the database call and their
work/elapsed time can correctly be associated with the FETCH which directly
follows. Sending the data to the client, however, must come after the FETCH, as
it does in all cases except for the initial FETCH. That is why I am thinking
that the first FETCH serves for bookkeeping of r, e, cr, cu, ..., but is not a
'real' FETCH and is out of order.
Henry
I
don't think it's PRIOR to the fetch -- I'd interpret this as being "THE"
fetch.
From what I understand by reading 10046 trace files - all the
events listed belong to the next call that follows (for the same cursor) in
the tracefile.
Therefore if you have
PARSE
WAIT 1
WAIT
2
EXEC
WAIT 3
WAIT 4
WAIT 5
FETCH
WAIT 6
FETCH
It
basically means that waits 1&2 "belong" to the EXEC call, waits 3-5 to the
1st FETCH call and wait 6 to the second FETCH call.
Stefan
On 7/13/07, Henry
Poras <henry@itasoftware.com>
wrote:
I've
been spending some time on my system trying to do time accounting
by
comparing output from sqlnet trace files and 10046 traces. While doing
this,
I've realized I don't understand what is going on with
the EXEC and FETCH
calls with simple SELECT statements. (this is on a MailScanner has detected a
possible fraud attempt from "10.2.0.3" claiming to be
10.2.0.3 db RedHat 2.6.9)
I ran a simple test case which returned
a single record. From looking at the
10046 trace it appears as though the
data is sent to the client before the
FETCH call. Huh? Is the initial
FETCH actually coupled with the EXEC and
just broken out in
the trace file at a later time?
=====================
PARSING IN
CURSOR #2 len=53 dep=0 uid=40 oct=3 lid=40 tim=1156580450666631
hv=1459047207 ad='9ae399a8'
select /* fetch test */ ename
from
emp
where rownum=1
END OF
STMT
PARSE
#2:c=6999,e=6990,p=0,cr=18,cu=0,mis=1,r=0,dep=0,og=1,tim=1156580450666627
BINDS
#2:
EXEC
#2:c=0,e=39,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,tim=1156580450666729
WAIT
#2: nam='SQL*Net message to client' ela= 4 driver id=1413697536
#bytes=1
p3=0 obj#=-1
tim=1156580450666769
<===
FETCH
#2:c=0,e=59,p=0,cr=5,cu=0,mis=0,r=1,dep=0,og=1,tim=1156580450666858
<===
WAIT #2: nam='SQL*Net message from client' ela= 1253 driver
id=1413697536
#bytes=1 p3=0 obj#=-1 tim=1156580450668168
FETCH
#2:c=0,e=2,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=0,tim=1156580450668205
WAIT
#2: nam='SQL*Net message to client' ela= 1 driver id=1413697536
#bytes=1
p3=0 obj#=-1 tim=1156580450668226
*** 2007-07-13 10:53:12.998
WAIT #2:
nam='SQL*Net message from client' ela= 11244427 driver
id=1413697536
#bytes=1 p3=0 obj#=-1 tim=1156580461912676
STAT #2 id=1 cnt=1 pid=0 pos=1
obj=0 op='COUNT STOPKEY (cr=5 pr=0 pw=0
time=55 us)'
STAT #2 id=2
cnt=1 pid=1 pos=1 obj=48029 op='TABLE ACCESS FULL EMP (cr=5
pr=0 pw=0
time=43 us)'
=====================
So after the EXEC, a packet is
sent to the client followed by a FETCH of one
record (r=1). After getting
confirmation back from the client (message from
client wait), sqlplus
does its final FETCH confirming no more data, and
sends this
to the client (message to client). The client then responds with
the next
sql to parse.
Looking at the sqlnet trace (level=SUPPORT), I see the
following packets:
1. nspsend of the SQL (after getting
this, the PARSE should happen)
2. nsprecv of the result set (header
information [ENAME], and the
data
[SMITH])
This is connected to the
'SQL*Net message to client' wait immediately
following the EXEC
3.
nspend (plen=21). I assume this is confirmation of receipt of the
data
packet
4. nsprecv of packet containing ORA-01403 no data
found
5. nspsend of next SQL
So the data is sent from the server
to the client prior to the initial
FETCH. The second FETCH confirms no
more data and that is sent to the client
after the FETCH.
I am
wondering if the initial EXEC actually does EXEC and FETCH, and
the
explicit FETCH call is just bookkeeping, not the real work. Maybe the
Oracle
kernal changed the way it does its work, but the 10046
display hasn't been
adjusted accordingly.
Has anyone else seen
this? Are there any other
explanations?
Thanks.
Henry
--
http://www.freelists.org/webpage/oracle-l
--
=========================
Stefan P
Knecht
Consultant
Infrastructure Managed Services
Trivadis AG
Europa-Strasse 5
CH-8152 Glattbrugg
Phone +41-44-808 70
20
Fax +41-808 70 12
Mobile +41-79-571 36 27
stefan.knecht@trivadis.com
http://www.trivadis.com
=========================