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

The autorace and 10046 are from separate sessions - I let the AT run overnight and killed the 10046 part way through.

The client (for both) is me on the DB machine at a SQL Plus prompt with a dedicated connection.

I'm starting to suspect the OS...but where?

On Wed, Sep 24, 2014 at 1:03 PM, Jonathan Lewis <jonathan_at_jlcomp.demon.co.uk
> wrote:

>
> 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-l