RE: 10046 L12 - Very long ela for 'SQL*Net message from client'?
Date: Wed, 24 Sep 2014 20:03:19 +0000
Message-ID: <CE70217733273F49A8A162EE074F64D901E1138A_at_exmbx05.thus.corp>
Something's not consistent here.
You have an array size of 15, a wait of 16 seconds between fetches, and 207,906 rows fetched - which should total about 2.5 days to complete !
How many of the waits were about 16 seconds, did they all appear in a single batch.
When you ran autotrace was the client elapsed time consistent with the server trace time ? What did the tkprof output give as the "time in the trace file".
Regards
Jonathan Lewis
http://jonathanlewis.wordpress.com
_at_jloracle
From: oracle-l-bounce_at_freelists.org [oracle-l-bounce_at_freelists.org] on behalf of Rich [richa03_at_gmail.com] Sent: 24 September 2014 17:38
To: Oracle-L Freelists
Subject: Fwd: 10046 L12 - Very long ela for 'SQL*Net message from client'?
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-lReceived on Wed Sep 24 2014 - 22:03:19 CEST