Re: 10046 L12 - Very long ela for 'SQL*Net message from client'?
- From: Rich <richa03@xxxxxxxxx>
- To: Martin Berger <martin.a.berger@xxxxxxxxx>
- Date: Wed, 24 Sep 2014 12:01:40 -0700
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@xxxxxxxxx> 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@xxxxxxxxx> 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
>>
>
>
Other related posts:
