RE: RE: TKPROF output

From: Ric Van Dyke <ric.van.dyke_at_hotsos.com>
Date: Thu, 31 Mar 2011 08:31:05 -0500
Message-ID: <C970F08BBE1E164AA8063E01502A71CF01A44DDC_at_WIN02.hotsos.com>

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_at_freelists.org [mailto:oracle-l-bounce_at_freelists.org] 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_at_uptime.be
tel +32(0)3 451 23 82
http://www.uptime.be
disclaimer: www.uptime.be/disclaimer

---
From: Niall Litchfield [mailto:niall.litchfield_at_gmail.com] 
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_at_uptime.be> 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_at_uptime.be
tel +32(0)3 451 23 82
http://www.uptime.be
disclaimer: www.uptime.be/disclaimer

From: Niall Litchfield [niall.litchfield_at_gmail.com]
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&apos;Hooge Freek" <Freek.DHooge_at_uptime.be> 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_at_uptime.be
tel +32(0)3 451 23 82
http://www.uptime.be
disclaimer: www.uptime.be/disclaimer
---
From: oracle-l-bounce_at_freelists.org [oracle-l-bounce_at_freelists.org] On Behalf Of lyallbarbour_at_sanfranmail.com [lyallbarbour_at_sanfranmail.com]
Sent: 30 March 2011 20:55

To: oracle-l_at_freelists.org
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--


http://www.freelists.org/webpage/oracle-l



-- 
Niall Litchfield
Oracle DBA
http://www.orawin.info
--
http://www.freelists.org/webpage/oracle-l


--
http://www.freelists.org/webpage/oracle-l

Received on Thu Mar 31 2011 - 08:31:05 CDT