RE: SQL*Net message from client

  • From: "Cary Millsap" <cary.millsap@xxxxxxxxxx>
  • To: <oracle-l@xxxxxxxxxxxxx>
  • Date: Wed, 2 Jun 2004 22:37:16 -0500

One point of clarification that comes to me upon seeing my own response
here... Just adding a COUNT column to the existing output isn't going to
reveal the answer you need. You really have to know something about the
distribution of snmfc durations (are they uniformly distributed? Or
skewed?). You'll only be able to see this by looking at the raw trace data.
It is impossible to see in the V$ data unless you poll the V$ fixed views
very rapidly (on the order of 100s of times per second).

Example: Imagine that you saw "total duration"="100 seconds", "call
count"="100 calls". How are the call durations distributed? Nine of ten
people will guess that each call is responsible for 1 second of time
consumption. But from the information at hand, it is entirely possible that
what really happened were ninety-nine calls at 0.001 seconds apiece, and one
call at 99.901 seconds. This is evidence of a completely different problem.
You can't tell just by looking at the total duration and the call count.
It's what in Chapter 1 of the book I refer to as the "red rock problem."


Cary Millsap
Hotsos Enterprises, Ltd.
http://www.hotsos.com
* Nullius in verba *

Upcoming events:
- Performance Diagnosis 101: 6/22 Pittsburgh, 7/20 Cleveland, 8/10 Boston
- SQL Optimization 101: 5/24 San Diego, 6/14 Chicago, 6/28 Denver
- Hotsos Symposium 2005: March 6-10 Dallas
- Visit www.hotsos.com for schedule details...


-----Original Message-----
From: oracle-l-bounce@xxxxxxxxxxxxx [mailto:oracle-l-bounce@xxxxxxxxxxxxx]
On Behalf Of Cary Millsap
Sent: Wednesday, June 02, 2004 10:25 PM
To: oracle-l@xxxxxxxxxxxxx
Subject: RE: SQL*Net message from client

Stalin,

I don't think the Oracle and OS versions really matter so much...

You're really not showing enough information to diagnose the problem. I
can't see enough detail from this V$*_EVENT query to know whether the time
waited is because of a large number of snmfc calls with similar durations
(with total time large because of so many calls), or if you have a small
number of long-latency snmfc calls.

If the problem is a large number of short-duration calls, then your attack
should be to reduce the number of dbcalls (parse, exec, fetch) that your
application makes. This is because snmfc calls exist between dbcalls. The
way to reduce the number of snmfc calls is thus to reduce the number of
dbcalls. How? Make sure that the application never parses inside of loops,
and use array processing instead of inserting/updating/deleting/fetching a
single row per dbcall.

If the problem is a small number of large-duration calls (or if the calls
are in excess of about 0.001 seconds if you're using IPC, or 0.010 seconds
if you're on a LAN, or about 0.100 seconds if you're on a WAN), then figure
out what's causing the individual call latency problem. Potential culprits
include overburdened or faulty network equipment, or simply an application
client process that's executing a lot of code path between dbcalls.

For a lot more detail, see Part III of the book called "Optimizing Oracle
Performance" if you have access to a copy.


Cary Millsap
Hotsos Enterprises, Ltd.
http://www.hotsos.com
* Nullius in verba *

Upcoming events:
- Performance Diagnosis 101: 6/22 Pittsburgh, 7/20 Cleveland, 8/10 Boston
- SQL Optimization 101: 5/24 San Diego, 6/14 Chicago, 6/28 Denver
- Hotsos Symposium 2005: March 6-10 Dallas
- Visit www.hotsos.com for schedule details...


-----Original Message-----
From: oracle-l-bounce@xxxxxxxxxxxxx [mailto:oracle-l-bounce@xxxxxxxxxxxxx]
On Behalf Of Subbiah, Stalin
Sent: Wednesday, June 02, 2004 9:26 PM
To: 'oracle-l@xxxxxxxxxxxxx'
Subject: RE: SQL*Net message from client

It would been better if I had given this information.

8.1.7.4/sol8 

-----Original Message-----
From: oracle-l-bounce@xxxxxxxxxxxxx [mailto:oracle-l-bounce@xxxxxxxxxxxxx]
On Behalf Of Subbiah, Stalin
Sent: Wednesday, June 02, 2004 7:15 PM
To: 'oracle-l@xxxxxxxxxxxxx'
Subject: SQL*Net message from client

Hi,

I'm trying to figure out a problem with "SQL*Net message from client" smfc
wait event albeit, they are considered a idle event. We have a batch script
running from a machine different than the database via cron. This script
summarizes data and inserts/updates rows one at a time. There will be lots
of individual insert/updates. Yeah we could have done this via single insert
select and update but we don't have control over it. Back to the problem,
looking at v$session_event for this batch session (see below), the top event
being 'SQL*Net message from client'. This batch is been running for almost
3hrs. 

EVENT                          TIME_WAITED
------------------------------ -----------
SQL*Net message from client         950067
STAT--CPU used by this session        6801
db file sequential read               5886
db file scattered read                 788
direct path read                       425
direct path write                      362
SQL*Net more data to client            299
log buffer space                        40
SQL*Net message to client               29
log file switch completion              20
latch free                              13
buffer busy waits                        0
file open                                0

Also I see the txn being active in v$transaction for this batch session.
Then I did 10046 trace via oradebug to see what's happening and I don't see
anything unusual other than smfc wait (most of it). How could I further
debug this issue without tampering batch script.

Snip from raw trc file...

*** SESSION ID:(103.24473) 2004-06-02 20:20:01.513 WAIT #6: nam='SQL*Net
message from client' ela= 46 p1=1413697536 p2=1 p3=0 =====================
PARSING IN CURSOR #5 len=130 dep=0 uid=19 oct=3 lid=19 tim=1248377751
hv=2027686058 ad='aefffd68'
SELECT count (*) from summary_hits_fact shf where
                   shf.page_hit_key = :p1 AND   shf.hit_date_key = :p2
END OF STMT
EXEC #5:c=0,e=0,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=4,tim=1248377751
WAIT #5: nam='SQL*Net message to client' ela= 0 p1=1413697536 p2=1 p3=0
FETCH #5:c=0,e=0,p=0,cr=3,cu=0,mis=0,r=1,dep=0,og=4,tim=1248377751
WAIT #5: nam='SQL*Net message from client' ela= 0 p1=1413697536 p2=1 p3=0
===================== PARSING IN CURSOR #7 len=340 dep=0 uid=19 oct=2 lid=19
tim=1248377751
hv=2447813369 ad='ac3b2208'
INSERT INTO summary_hits_fact
             (page_hit_key, hit_date_key, hit_count)
              SELECT hf.page_hit_key, hf.hit_date_key, count(*)
                 FROM hits_fact hf
                 WHERE hf.page_hit_key = :p1
                 AND   hf.hit_date_key = :p2
                 GROUP BY hf.page_hit_key, hf.hit_date_key END OF STMT EXEC
#7:c=0,e=0,p=0,cr=3,cu=4,mis=0,r=1,dep=0,og=4,tim=1248377751
WAIT #7: nam='SQL*Net message to client' ela= 0 p1=1413697536 p2=1 p3=0 WAIT
#7: nam='SQL*Net message from client' ela= 46 p1=1413697536 p2=1 p3=0 EXEC
#5:c=0,e=0,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=4,tim=1248377797
WAIT #5: nam='SQL*Net message to client' ela= 0 p1=1413697536 p2=1 p3=0
FETCH #5:c=0,e=0,p=0,cr=3,cu=0,mis=0,r=1,dep=0,og=4,tim=1248377797
WAIT #5: nam='SQL*Net message from client' ela= 0 p1=1413697536 p2=1 p3=0
===================== PARSING IN CURSOR #6 len=336 dep=0 uid=19 oct=6 lid=19
tim=1248377797
hv=3885370321 ad='a7027a74'
UPDATE summary_hits_fact shf
             SET (hit_count) = 
             (SELECT count(*)
                 FROM hits_fact hf
                 WHERE shf.page_hit_key = hf.page_hit_key
                 AND   shf.hit_date_key = hf.hit_date_key)
             WHERE shf.page_hit_key = :p1
             AND   shf.hit_date_key = :p2
END OF STMT
EXEC #6:c=0,e=0,p=0,cr=6,cu=2,mis=0,r=1,dep=0,og=4,tim=1248377797
WAIT #6: nam='SQL*Net message to client' ela= 0 p1=1413697536 p2=1 p3=0 WAIT
#6: nam='SQL*Net message from client' ela= 46 p1=1413697536 p2=1 p3=0 EXEC
#5:c=0,e=0,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=4,tim=1248377843
WAIT #5: nam='SQL*Net message to client' ela= 0 p1=1413697536 p2=1 p3=0
FETCH #5:c=0,e=0,p=0,cr=3,cu=0,mis=0,r=1,dep=0,og=4,tim=1248377843
WAIT #5: nam='SQL*Net message from client' ela= 0 p1=1413697536 p2=1 p3=0
EXEC #6:c=0,e=0,p=0,cr=6,cu=2,mis=0,r=1,dep=0,og=4,tim=1248377843
WAIT #6: nam='SQL*Net message to client' ela= 0 p1=1413697536 p2=1 p3=0
..... Goes on.


Thanks,
Stalin
----------------------------------------------------------------
Please see the official ORACLE-L FAQ: http://www.orafaq.com
----------------------------------------------------------------
To unsubscribe send email to:  oracle-l-request@xxxxxxxxxxxxx put
'unsubscribe' in the subject line.
--
Archives are at //www.freelists.org/archives/oracle-l/
FAQ is at //www.freelists.org/help/fom-serve/cache/1.html
-----------------------------------------------------------------
----------------------------------------------------------------
Please see the official ORACLE-L FAQ: http://www.orafaq.com
----------------------------------------------------------------
To unsubscribe send email to:  oracle-l-request@xxxxxxxxxxxxx
put 'unsubscribe' in the subject line.
--
Archives are at //www.freelists.org/archives/oracle-l/
FAQ is at //www.freelists.org/help/fom-serve/cache/1.html
-----------------------------------------------------------------

----------------------------------------------------------------
Please see the official ORACLE-L FAQ: http://www.orafaq.com
----------------------------------------------------------------
To unsubscribe send email to:  oracle-l-request@xxxxxxxxxxxxx
put 'unsubscribe' in the subject line.
--
Archives are at //www.freelists.org/archives/oracle-l/
FAQ is at //www.freelists.org/help/fom-serve/cache/1.html
-----------------------------------------------------------------

----------------------------------------------------------------
Please see the official ORACLE-L FAQ: http://www.orafaq.com
----------------------------------------------------------------
To unsubscribe send email to:  oracle-l-request@xxxxxxxxxxxxx
put 'unsubscribe' in the subject line.
--
Archives are at //www.freelists.org/archives/oracle-l/
FAQ is at //www.freelists.org/help/fom-serve/cache/1.html
-----------------------------------------------------------------

Other related posts: