RE: 10046 L12 - Very long ela for 'SQL*Net message from client'?

From: Dimensional DBA <dimensional.dba_at_comcast.net>
Date: Wed, 24 Sep 2014 12:49:15 -0700
Message-ID: <017101cfd830$9fc1ecf0$df45c6d0$_at_comcast.net>



If you are in control of the application and it is on the database server in a dedicated session then you can turn on SQLnet tracing on the DB server to go along with your actual session tracing and determine which part of the component is consuming the time.

An strace would be a good choice too on your session.        

Matthew Parker

Chief Technologist

425-891-7934 (cell)

Dimensional.dba_at_comcast.net

 <http://www.linkedin.com/pub/matthew-parker/6/51b/944/> View Matthew Parker's profile on LinkedIn  

From: oracle-l-bounce_at_freelists.org [mailto:oracle-l-bounce_at_freelists.org] On Behalf Of Rich Sent: Wednesday, September 24, 2014 12:02 PM To: Martin Berger
Cc: Oracle-L Freelists
Subject: Re: 10046 L12 - Very long ela for 'SQL*Net message from client'?  

Thanks Martin!

I agree, it looks external to Oracle, but where? There is no "network" or external application since I'm in a dedicated session on the DB server. I know it might use the loopback interface to "send" the data... How do I continue to troubleshoot at the OS?

I think I need to get this into Dev (with strace)...but that will be difficult.

Thanks again,
Rich

On Sep 24, 2014 11:38 AM, "Martin Berger" <martin.a.berger_at_gmail.com> wrote:

Hi Rich,  

Oracle calls 'SQL*Net message from client' an "idle event" as the DB has nothing to do at this time.

Others call it "think time" as the user (or application) "think" about the results returned and what to do next.

In general you can not tell so much about this time, as it's spend outside of the DB and therefore outside of the 10046 tracing system.  

In your case it seems a roundtrip FETCH; client "thinks" for 16 sec; next FETCH; ...  

You should know the border of 'SQL*Net message from client' is still within the Oracle software. So everything "outside" (e.g. still the kernel or Network card driver) is already counted for 'SQL*Net message from client'.  

I'd go and check what is going on between 'outside of the DB' (still on DB-Server) and the Application.  

As a side information you can check the array size (probably not that easy). In general it makes a difference if you send 100 records one-by-one (and wait 16 sec at each roundtrip) or you send 50 records at a time and (if the think-time is stable) only 16 sec in between.  

I hope that's an acceptable entry to your question - even the solution will need further investigations.  

Martin    

On Wed, Sep 24, 2014 at 6:38 PM, Rich <richa03_at_gmail.com> wrote:

Hi List,
This is 11.1.0.7 on Oracle Linux 5 U3 (Enterprise Linux Server release 5.3 (Carthage) (kernel 2.6.18-128.el5))

rpm -qf /etc/redhat-release
enterprise-release-5-0.0.17

(I know the version is “very” old, but that’s where we are right now.)

I seem to remember a post by Tanel (or was it Kyle?) a while back about this/these types of waits (SQL*Net), however, my Google fu is not working for me right now.

Snip from 10046 level 12 trace from a dedicated SQL*Plus session on the DB server: …
*** 2014-09-24 08:03:20.151
WAIT #2: nam='SQL*Net message from client' ela= 16701919 driver id=1650815232 #bytes=1 p3=0 obj#=1237502 tim=1411571000151138 WAIT #2: nam='SQL*Net message to client' ela= 1 driver id=1650815232 #bytes=1 p3=0 obj#=1237502 tim=1411571000151302 FETCH #2:c=1000,e=0,p=0,cr=0,cu=0,mis=0,r=15,dep=0,og=1,plh=133634354,tim=1411571000143712

  • 2014-09-24 08:03:36.853 WAIT #2: nam='SQL*Net message from client' ela= 16702053 driver id=1650815232 #bytes=1 p3=0 obj#=1237502 tim=1411571016853884 WAIT #2: nam='SQL*Net message to client' ela= 1 driver id=1650815232 #bytes=1 p3=0 obj#=1237502 tim=1411571016854041 FETCH #2:c=0,e=0,p=0,cr=0,cu=0,mis=0,r=15,dep=0,og=1,plh=133634354,tim=1411571016838765
  • 2014-09-24 08:03:53.541 WAIT #2: nam='SQL*Net message from client' ela= 16686602 driver id=1650815232 #bytes=1 p3=0 obj#=1237502 tim=1411571033541263 WAIT #2: nam='SQL*Net message to client' ela= 2 driver id=1650815232 #bytes=1 p3=0 obj#=1237502 tim=1411571033541424 FETCH #2:c=1000,e=0,p=0,cr=0,cu=0,mis=0,r=15,dep=0,og=1,plh=133634354,tim=1411571033533874 …

From client is consistently ~16sec!

Autotrace of the statement looks like:

207963 rows selected.

Execution Plan



Plan hash value: 133634354  
| Id  | Operation                     | Name              | Rows  | Bytes |TempSpc| Cost (%CPU)| Time     |
-----------------------------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT              |                   |  5759 |  2991K|       | 16679   (1)| 00:03:21 |

|* 1 | TABLE ACCESS FULL | PFM_AUDIT_LOG_HDR | 1 | 22 | | 309 (1)| 00:00:04 |
| 2 | SORT ORDER BY | | 5759 | 2991K| 9224K| 16679 (1)| 00:03:21 |
|* 3 | HASH JOIN | | 5759 | 2991K| | 16026 (1)| 00:03:13 |
|* 4 | INDEX FAST FULL SCAN | PFM_COMPANY_AI1 | 331 | 11916 | | 60 (2)| 00:00:01 |
|* 5 | TABLE ACCESS BY INDEX ROWID| PFM_POS | 17428 | 8441K| | 15965 (1)| 00:03:12 |
|* 6 | INDEX RANGE SCAN | PFM_POS_AI1 | 18366 | | | 8013 (1)| 00:01:37 |
-----------------------------------------------------------------------------------------------------------

Predicate Information (identified by operation id):


   1 - filter("MODEL_TYPE_ID"='POS' AND TO_NUMBER("DOCUMENT_OID")=:B1)
   3 - access("POS"."COMPANY_ENSOID"="VER_ENSOID")
   4 - filter(UPPER("NAME") LIKE 'SOME STRING' ESCAPE  AND "VER_LATEST_VEROID" IS NOT NULL)
   5 - filter("POS"."TRANS_SUBTYPE_ID"='4')
   6 - access("POS"."TRANS_END_DATE">=TO_DATE(' 2011-04-01 00:00:00', 'syyyy-mm-dd hh24:mi:ss')
              AND "POS"."TRANS_END_DATE"<=TO_DATE(' 2014-03-31 23:59:59', 'syyyy-mm-dd hh24:mi:ss'))
       filter(UPPER(TO_CHAR("POS"."HIDDEN")) LIKE '0' ESCAPE  AND "POS"."VER_LATEST_VEROID" IS NOT NULL)

Statistics


          1  recursive calls
          0  db block gets
    264266641  consistent gets – I know it might be better to just FTS the POS table rather than use the index, however, I’m trying to understand why the long ‘SQL*Net message from client’ waits
          0  physical reads
          0  redo size
   45412064  bytes sent via SQL*Net to client – this is “only” ~43MB
     157869  bytes received via SQL*Net from client - ~150KB
      13866  SQL*Net roundtrips to/from client – might be able to reduce this with arraysize (currently 15) and/or SDU/TDU/IO Buffers (currently default AFAIK), but, still why the long ‘SQL*Net message from client’ waits

          1  sorts (memory)
          0  sorts (disk)

     207963  rows processed

The POC table is very wide (533 columns with type spread of 237 number, 17 date and 213 varchar2 – no LOB) - AVG_ROW_LEN is 496 from DBA_TABLES (last analyzed 15SEP2014). The PFM_AUDIT_LOG_HDR table is very small (1126 blocks from DBA_TABLES – last analyzed 22SEP2014).

We could do a SQL Net trace, however, on this version, I think it’d be have to be for all traffic which is not doable in the current environment… Also, there’s no strace on production (where I am right now). Might be able to try to repro in DEV, however, it might be difficult to get time from them…

Any help would be greatly appreciated.

Thanks,
Rich  

--
http://www.freelists.org/webpage/oracle-l
Received on Wed Sep 24 2014 - 21:49:15 CEST

Original text of this message