RE: RE: TKPROF output
- From: "Ric Van Dyke" <ric.van.dyke@xxxxxxxxxx>
- To: <Freek.DHooge@xxxxxxxxx>, "Niall Litchfield" <niall.litchfield@xxxxxxxxx>
- Date: Thu, 31 Mar 2011 08:31:05 -0500
SQL*Net to Client doesn't measure what it looks like. It really seems to
measure how long it takes to assemble the message that is going to be sent to
the client. It doesn't measure the actual send.
The entire round trip (send, handshaking, wait for next command) is all in
SQL*Net FROM client. As Ron Crisco has mentioned this is well documented in
Cary's book "Optimizing Oracle Performance".
It appears there are two things that need to be investigated:
1) Arraysize appears to be too small. Maybe these are huge rows, but even so,
a larger array size seems needed. Fewer round trips, fewer fetches, fewer
SQL*Net to/from Client messages.
2) What is the client side doing with the data? Does it really need 164,741
rows? The average SQL*Net seems to be about 0.0036 seconds which does seem
reasonably fast, but when you do over 27,000 calls it adds up!
-----------------------
Ric Van Dyke
Hotsos Enterprises
-----------------------
The 10th Hotsos Symposium
4-8 March 2012 Start making plans now!
-----Original Message-----
From: oracle-l-bounce@xxxxxxxxxxxxx [mailto:oracle-l-bounce@xxxxxxxxxxxxx] On
Behalf Of D'Hooge Freek
Sent: Thursday, March 31, 2011 8:24 AM
To: Niall Litchfield
Cc: ORACLE-L
Subject: RE: RE: TKPROF output
Niall,
Yes you are right.
As I come to think of it 0.000000364 seconds per sql*net message to client is
maybe a tad low to be realistic :-)
I also verified with some traces I had from my systems and the total time spend
on sql*net message to client seems to be always 0 (or near zero), while the
time spend on sql*net message from client is more realistic.
Regards,
Freek D'Hooge
Uptime
Oracle Database Administrator
email: freek.dhooge@xxxxxxxxx
tel +32(0)3 451 23 82
http://www.uptime.be
disclaimer: www.uptime.be/disclaimer
---
From: Niall Litchfield [mailto:niall.litchfield@xxxxxxxxx]
Sent: donderdag 31 maart 2011 12:57
To: D'Hooge Freek
Cc: ORACLE-L
Subject: Re: RE: TKPROF output
I think the SQL*Net Message to/from Client events are (a bit) unfortunately
named. They are (IIRC - strace would show) sendmsg and recvmsg syscalls and
associated timings. As the link send by Remigiusz describes the send call ends
when the data is placed in the send buffer and the receive call when the
response (and data) is received. This means effectively that SQL*Net message
from client covers pretty much the whole latency and message to client just
signals the start (I'd be really geekily interested if anyone has examples of
SQL*Net Message to client syscalls taking any length of time at all.) This is
pretty much no use for telling us if the network is slow, the app server is
slow or the user is kicking back watching the cricket. It does tell us though
that time "outside" the database is being spent.
I too thought of asking for the histograms, but I don't think there will be
many slow examples. Total time spent in 27k calls was 100s (with 1s of that
spent in 1 call) that leaves 99s for the remaining and too many cs scale
requests must mean a number of sub ms events which is unlikely on normal
networks. I would like to see the old system data.
On Thu, Mar 31, 2011 at 7:41 AM, D'Hooge Freek <Freek.DHooge@xxxxxxxxx> wrote:
True, but compaired to the time spend for sending the data it seems high.
Also the max wait time is 1 second. It would be interesting to see the
histogram for this.
Lyall,
Can you run orasrp on the raw trace file to get the histograms
(http://www.oracledba.ru/orasrp/)
Remigiusz,
Thanks for the link, I will certainly check it out.
regards,
Freek D'Hooge
Uptime
Oracle Database Administrator
email: freek.dhooge@xxxxxxxxx
tel +32(0)3 451 23 82
http://www.uptime.be
disclaimer: www.uptime.be/disclaimer
From: Niall Litchfield [niall.litchfield@xxxxxxxxx]
Sent: 31 March 2011 08:26
To: D'Hooge Freek; ORACLE-L
Subject: Re: RE: TKPROF output
Freek, I don't think the comms are slow per se. If my math is right the avg
wait is 3ms . There are a lot of them though. Of course we don't know rowsize
or what the original system looks like.
On 31 Mar 2011 07:03, "D'Hooge Freek" <Freek.DHooge@xxxxxxxxx> wrote:
Hi,
The main wait time is "sql*net message from client", meaning that you are
waiting on response from the aplication server.
Can you check in the raw trace file if these waits are happening between the
fetches or not?
If they are happening between the fetches, it means that the application server
is slow to request more rows from the query result.
Reason for this could be some processing that happens on the application server
or maybe a network problem (like a wrong dns server on the application server).
If the waits are happening after all the fetches are completed, then these
waits are probably not relevant (unless you are sure that the trace was stopped
at the moment the application showed the result of the query).
How did you trace this session?
regards,
Freek D'Hooge
Uptime
Oracle Database Administrator
email: freek.dhooge@xxxxxxxxx
tel +32(0)3 451 23 82
http://www.uptime.be
disclaimer: www.uptime.be/disclaimer
---
From: oracle-l-bounce@xxxxxxxxxxxxx [oracle-l-bounce@xxxxxxxxxxxxx] On Behalf
Of lyallbarbour@xxxxxxxxxxxxxxx [lyallbarbour@xxxxxxxxxxxxxxx]
Sent: 30 March 2011 20:55
To: oracle-l@xxxxxxxxxxxxx
Subject: TKPROF output
Trying to understand Fetch in a TKPROF output. We have an application on Oracle
Apps Server 10.1 D...
SQL*Net message from client 27457 1.07 100.33--
//www.freelists.org/webpage/oracle-l
--
Niall Litchfield
Oracle DBA
http://www.orawin.info
--
//www.freelists.org/webpage/oracle-l
--
//www.freelists.org/webpage/oracle-l
Other related posts:
