From oracle-l-bounce@freelists.org Wed Jun 2 22:35:14 2004 Return-Path: Received: from air189.startdedicated.com (root@localhost) by orafaq.com (8.11.6/8.11.6) with ESMTP id i533Yxi07809 for ; Wed, 2 Jun 2004 22:35:09 -0500 X-ClientAddr: 206.53.239.180 Received: from turing.freelists.org (freelists-180.iquest.net [206.53.239.180]) by air189.startdedicated.com (8.11.6/8.11.6) with ESMTP id i533Yh607794 for ; Wed, 2 Jun 2004 22:34:54 -0500 Received: from localhost (localhost [127.0.0.1]) by turing.freelists.org (Avenir Technologies Mail Multiplex) with ESMTP id 584E872C341; Wed, 2 Jun 2004 22:21:17 -0500 (EST) Received: from turing.freelists.org ([127.0.0.1]) by localhost (turing [127.0.0.1]) (amavisd-new, port 10024) with ESMTP id 31028-29; Wed, 2 Jun 2004 22:21:17 -0500 (EST) Received: from turing (localhost [127.0.0.1]) by turing.freelists.org (Avenir Technologies Mail Multiplex) with ESMTP id D314B72C5B5; Wed, 2 Jun 2004 22:21:14 -0500 (EST) Received: with ECARTIS (v1.0.0; list oracle-l); Wed, 02 Jun 2004 22:19:51 -0500 (EST) X-Original-To: oracle-l@freelists.org Delivered-To: oracle-l@freelists.org Received: from localhost (localhost [127.0.0.1]) by turing.freelists.org (Avenir Technologies Mail Multiplex) with ESMTP id 91FC872C1FB for ; Wed, 2 Jun 2004 22:19:50 -0500 (EST) Received: from turing.freelists.org ([127.0.0.1]) by localhost (turing [127.0.0.1]) (amavisd-new, port 10024) with ESMTP id 29970-90 for ; Wed, 2 Jun 2004 22:19:50 -0500 (EST) Received: from www.hotsos.com (hotsos.com [209.120.206.15]) by turing.freelists.org (Avenir Technologies Mail Multiplex) with ESMTP id 0175172C11F for ; Wed, 2 Jun 2004 22:19:50 -0500 (EST) Received: from CVMLAP02 (66.169.163.33.ts46v-12.otne2.ftwrth.tx.charter.com [66.169.163.33]) (authenticated (0 bits)) by www.hotsos.com (8.12.11/8.11.0) with ESMTP id i533c8aU001549 for ; Wed, 2 Jun 2004 22:38:08 -0500 From: "Cary Millsap" To: Subject: RE: SQL*Net message from client Date: Wed, 2 Jun 2004 22:37:16 -0500 Message-ID: <013f01c4491c$143b5080$6801a8c0@CVMLAP02> MIME-Version: 1.0 Content-Type: text/plain; charset="us-ascii" Content-Transfer-Encoding: 8bit X-MIME-Autoconverted: from quoted-printable to 8bit by Ecartis X-Priority: 3 (Normal) X-MSMail-Priority: Normal X-Mailer: Microsoft Outlook, Build 10.0.6626 X-MimeOLE: Produced By Microsoft MimeOLE V6.00.2800.1409 In-Reply-To: <013c01c4491a$692eab20$6801a8c0@CVMLAP02> Importance: Normal X-Virus-Scanned: by amavisd-new at freelists.org X-archive-position: 1833 X-ecartis-version: Ecartis v1.0.0 Sender: oracle-l-bounce@freelists.org Errors-To: oracle-l-bounce@freelists.org X-original-sender: cary.millsap@hotsos.com Precedence: normal Reply-To: oracle-l@freelists.org X-list: oracle-l X-Virus-Scanned: by amavisd-new at freelists.org 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@freelists.org [mailto:oracle-l-bounce@freelists.org] On Behalf Of Cary Millsap Sent: Wednesday, June 02, 2004 10:25 PM To: oracle-l@freelists.org 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@freelists.org [mailto:oracle-l-bounce@freelists.org] On Behalf Of Subbiah, Stalin Sent: Wednesday, June 02, 2004 9:26 PM To: 'oracle-l@freelists.org' 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@freelists.org [mailto:oracle-l-bounce@freelists.org] On Behalf Of Subbiah, Stalin Sent: Wednesday, June 02, 2004 7:15 PM To: 'oracle-l@freelists.org' 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@freelists.org put 'unsubscribe' in the subject line. -- Archives are at http://www.freelists.org/archives/oracle-l/ FAQ is at http://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@freelists.org put 'unsubscribe' in the subject line. -- Archives are at http://www.freelists.org/archives/oracle-l/ FAQ is at http://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@freelists.org put 'unsubscribe' in the subject line. -- Archives are at http://www.freelists.org/archives/oracle-l/ FAQ is at http://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@freelists.org put 'unsubscribe' in the subject line. -- Archives are at http://www.freelists.org/archives/oracle-l/ FAQ is at http://www.freelists.org/help/fom-serve/cache/1.html -----------------------------------------------------------------