Re: 10046 L12 - Very long ela for 'SQL*Net message from client'?
- From: Martin Berger <martin.a.berger@xxxxxxxxx>
- To: richa03@xxxxxxxxx
- Date: Wed, 24 Sep 2014 20:38:25 +0200
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:
