Oracle 12c TABLE ACCESS BY INDEX ROWID BATCHED


Few days back exploring 12c DB on my small VM found this little new feature. Here is the output from 11gR2


SQL_ID 3a936zyv7jupf, child number 0
-------------------------------------
SELECT w.WAREHOUSE_NAME, w.LOCATION_ID, i.PRODUCT_ID,i.QUANTITY_ON_HAND
 FROM WAREHOUSES w, INVENTORIES i WHERE i.PRODUCT_ID IN (10,5,1)
 AND w.WAREHOUSE_ID = i.WAREHOUSE_ID

Plan hash value: 2661993828

---------------------------------------------------------------------------------------------------------------------------------------------------------------------------
| Id | Operation | Name | Starts | E-Rows |E-Bytes| Cost (%CPU)| E-Time | A-Rows | A-Time | Buffers | Reads | OMem | 1Mem | Used-Mem |
---------------------------------------------------------------------------------------------------------------------------------------------------------------------------
| 0 | SELECT STATEMENT | | 1 | | | 61 (100)| | 2604 |00:00:00.09 | 40 | 30 | | | |
|* 1 | HASH JOIN | | 1 | 2700 | 105K| 61 (2)| 00:00:01 | 2604 |00:00:00.09 | 40 | 30 | 947K| 947K| 1298K (0)|
| 2 | TABLE ACCESS FULL | WAREHOUSES | 1 | 1000 | 26000 | 2 (0)| 00:00:01 | 1000 |00:00:00.01 | 6 | 6 | | | |
| 3 | INLIST ITERATOR | | 1 | | | | | 2604 |00:00:00.07 | 34 | 24 | | | |
| 4 | TABLE ACCESS BY INDEX ROWID| INVENTORIES | 3 | 2700 | 37800 | 58 (0)| 00:00:01 | 2604 |00:00:00.07 | 34 | 24 | | | |
|* 5 | INDEX RANGE SCAN | INV_PROD_IX | 3 | 2700 | | 8 (0)| 00:00:01 | 2604 |00:00:00.05 | 17 | 10 | | | |
---------------------------------------------------------------------------------------------------------------------------------------------------------------------------

As you can see it’s a simple query, but the point which i want to make here is since INVENTORIES table is been accesed through rowid’s which we received from it’s child operation i.e. Index range scan. Now till 11gr2 this operation was doing a single IO’s (db file sequential read) to get rowid’s. Now here is same execution tree from 12C


SELECT w.WAREHOUSE_NAME, w.LOCATION_ID, i.PRODUCT_ID,i.QUANTITY_ON_HAND
 FROM WAREHOUSES w, INVENTORIES i
 WHERE i.PRODUCT_ID IN (10,5,1)
 AND w.WAREHOUSE_ID = i.WAREHOUSE_ID

call count cpu elapsed disk query current rows
------- ------ -------- ---------- ---------- ---------- ---------- ----------
Parse 1 0.01 0.02 4 127 0 0
Execute 1 0.00 0.00 0 0 0 0
Fetch 4 0.16 0.19 63 42 0 2604
------- ------ -------- ---------- ---------- ---------- ---------- ----------
total 6 0.18 0.22 67 169 0 2604

Rows (1st) Rows (avg) Rows (max) Row Source Operation
---------- ---------- ---------- ---------------------------------------------------
 2604 2604 2604 HASH JOIN (cr=42 pr=63 pw=0 time=176064 us cost=64 size=108000 card=2700)
 1000 1000 1000 NESTED LOOPS (cr=7 pr=6 pw=0 time=29011 us)
 1000 1000 1000 NESTED LOOPS (cr=7 pr=6 pw=0 time=21009 us cost=64 size=108000 card=2700)
 1000 1000 1000 STATISTICS COLLECTOR (cr=7 pr=6 pw=0 time=14006 us)
 1000 1000 1000 TABLE ACCESS STORAGE FULL WAREHOUSES (cr=7 pr=6 pw=0 time=7002 us cost=4 size=26000 card=1000)
 0 0 0 INLIST ITERATOR (cr=0 pr=0 pw=0 time=0 us)
 0 0 0 INDEX UNIQUE SCAN INVENTORY_PK (cr=0 pr=0 pw=0 time=0 us cost=8 size=0 card=2700)(object id 92293)
 0 0 0 TABLE ACCESS BY INDEX ROWID INVENTORIES (cr=0 pr=0 pw=0 time=0 us cost=60 size=42 card=3)
 2604 2604 2604 INLIST ITERATOR (cr=35 pr=57 pw=0 time=74024 us)
 2604 2604 2604 TABLE ACCESS BY INDEX ROWID BATCHED INVENTORIES (cr=35 pr=57 pw=0 time=49014 us cost=60 size=37800 card=2700)
 2604 2604 2604 INDEX RANGE SCAN INV_PROD_IX (cr=17 pr=25 pw=0 time=22003 us cost=8 size=0 card=2700)(object id 92372)
Elapsed times include waiting on following events:
 Event waited on Times Max. Wait Total Waited
 ---------------------------------------- Waited ---------- ------------
 SQL*Net message to client 4 0.00 0.00
 Disk file operations I/O 1 0.00 0.00
 db file sequential read 2 0.00 0.00
 db file scattered read 8 0.00 0.00
 SQL*Net message from client 3 0.41 0.80
 SQL*Net more data to client 10 0.00 0.00

If we see there is a new operation called “TABLE ACCESS BY INDEX ROWID BATCHED” which from wait events can see is doing multi block reads and here is data from trace file.


WAIT #140517340780192: nam='db file scattered read' ela= 1000 file#=6 block#=176960 blocks=8 obj#=92372 tim=6142407268
WAIT #140517340780192: nam='db file sequential read' ela= 1000 file#=6 block#=179575 blocks=1 obj#=92372 tim=6142408268
WAIT #140517340780192: nam='db file scattered read' ela= 0 file#=6 block#=176968 blocks=8 obj#=92372 tim=6142455285
WAIT #140517340780192: nam='db file scattered read' ela= 2000 file#=6 block#=176976 blocks=8 obj#=92372 tim=6142923447

count of blocks indeed match with CR on index and moreover doing multi block reads. Now to switch off this feature you can use hints or setup below parameters


SELECT /*+ NO_BATCH_TABLE_ACCESS_BY_ROWID(i)*/ w.WAREHOUSE_NAME, w.LOCATION_ID, i.PRODUCT_ID,i.QUANTITY_ON_HAND
 FROM WAREHOUSES w, INVENTORIES i
 WHERE i.PRODUCT_ID IN (10,5,1)
 AND w.WAREHOUSE_ID = i.WAREHOUSE_ID;

or

alter session set "_optimizer_batch_table_access_by_rowid"=FALSE;

------------------------------------------------------------------------------------------------------------------------------------------------------------------
| Id | Operation | Name | Starts | E-Rows |E-Bytes| Cost (%CPU)| E-Time | A-Rows | A-Time | Buffers | OMem | 1Mem | Used-Mem |
------------------------------------------------------------------------------------------------------------------------------------------------------------------
| 0 | SELECT STATEMENT | | 1 | | | 64 (100)| | 2604 |00:00:00.19 | 42 | | | |
|* 1 | HASH JOIN | | 1 | 2700 | 105K| 64 (0)| 00:00:01 | 2604 |00:00:00.19 | 42 | 1160K| 1160K| 1293K (0)|
| 2 | TABLE ACCESS STORAGE FULL | WAREHOUSES | 1 | 1000 | 26000 | 4 (0)| 00:00:01 | 1000 |00:00:00.01 | 7 | | | |
| 3 | INLIST ITERATOR | | 1 | | | | | 2604 |00:00:00.09 | 35 | | | |
| 4 | TABLE ACCESS BY INDEX ROWID| INVENTORIES | 3 | 2700 | 37800 | 60 (0)| 00:00:01 | 2604 |00:00:00.07 | 35 | | | |
|* 5 | INDEX RANGE SCAN | INV_PROD_IX | 3 | 2700 | | 8 (0)| 00:00:01 | 2604 |00:00:00.02 | 17 | | | |
------------------------------------------------------------------------------------------------------------------------------------------------------------------

Nice, new feature but note sure how much it will be helpful in OLTP !!!.

ON AIX Oracle Process ULSA Memory

It’s been long time i have blogged anything but few days back was researching some issue with my friend and came to know this issue not exactly an issue but a feature which can consume more oracle process memory on AIX due to Large USLA Heap Segment.

Here are the details for oracle process consuming memory while doing nothing


Unit: page
-------------------------------------------------------------------------------
Pid Command Inuse Pin Pgsp Virtual
19071118 oracle 2131887 8832 1264 2133518
...............................................................................
SYSTEM segments Inuse Pin Pgsp Virtual
12619 8784 528 13067
Vsid Esid Type Description PSize Inuse Pin Pgsp Virtual
20002 0 work kernel segment m 617 549 33 645
50005 9ffffffd work shared library sm 2699 0 0 2699
e000e 9ffffffe work shared library sm 37 0 0 37
31cab9b 8fffffff work private load data s 11 0 0 11
...............................................................................
EXCLUSIVE segments Inuse Pin Pgsp Virtual
4401 48 0 4401
Vsid Esid Type Description PSize Inuse Pin Pgsp Virtual
370aff7 11 work text data BSS heap m 125 0 0 125 <--Around 8MB Doing Nothing
380af07 80020014 work USLA heap sm 1873 0 0 1873 <--Around 7.3 MB In USLA
5aa8dd 9001000a work shared library data m 23 0 0 23
2afaa28 f00000002 work process private m 5 3 0 5
3945314 ffffffff work application stack m 4 0 0 4
22da2aa 8001000a work private load data m 1 0 0 1
3bfaf38 fffffffd work application stack m 0 0 0 0
204ae83 fffffff2 work application stack m 0 0 0 0
38caf0b fffffff9 work application stack m 0 0 0 0
21caa9b fffffff8 work application stack m 0 0 0 0
15a492 fffffff4 work application stack m 0 0 0 0
5e3cdd fffffff5 work application stack m 0 0 0 0
1788dfa fffffff3 work application stack m 0 0 0 0
17aadfd fffffffa work application stack m 0 0 0 0
222aea5 fffffff0 work application stack m 0 0 0 0
1c9ad4e fffffffc work application stack m 0 0 0 0

As, you can see oracle process is using around 8MB memory(64k Pages), But interesting thing is second line where it’s using 7 MB of memory and it’s persistence across all process. So, imagine if you have 1000 session’s than this will be  6.8 GB of whooping memory.

Here is the explanation from oracle note

11gR2/Aix – Dedicated Server Processes Have Large Usla Heap Segment Compared To Older Versions (Doc ID 1260095.1)

CAUSE

In 11gR2, the Oracle server process (oracle binary) is linked with an additional linker options:-bexpful and -brtllib.The -bexpfull and -brtllib linker options were added to implement the Oracle hot patching functionality.

In the previous releases of Oracle 11gR1, 10g and 9i, the -bexpful and -brtllib ld options are not used.

USLA heap usage from an “svmon -p of an Oracle server process” would be around 1800 4KB pages (~7MB) and this USLA heap is process private. This is needed for Oracle on-line patching: a new functionality implemented in 11gR2. With this feature, global symbols in the Oracle binary are saved in USLA heap for resolving the new object files in the shared libraries included in a patch.

Oracle has created fix in Bug 10190759
Abstract: PROCESSES CONSUMING ADDITIONAL MEMORY DUE TO ‘USLA HEAP’

Fix Notes:
With this interim patch it is possible to relink oracle by specifying :
make -f ins_rdbms.mk ‘EXP_OPTS=$(EXP_OPTS_OFF)’ ioracle
to remove -bexpfull and -brtllib link options and
make -f ins_rdbms.mk ‘EXP_OPTS=$(EXP_OPTS_ON)’ ioracle
to add them back.

ORA-21500 Bug for 11gR1 Client Using XMLTYPE

Recently one of the user got ORA-21500 and this was due to bug in 11gr1 client. User has 11gr1 client version which connects to 11gr2 DB and this bug is related to securefile handling in 11gr1 client. But, this post it not about going into much deeper details but  just wanted to document what i learned.

CREATE TABLE TARAL.BUG_TEST1(ID NUMBER(38,0) NOT NULL, XCOL1 SYS.XMLTYPE)
 XMLTYPE COLUMN XCOL1 STORE AS SECUREFILE BINARY XML(TABLESPACE USERS ENABLE STORAGE IN ROW CHUNK 8192);

CREATE TABLE TARAL.BUG_TEST2(ID NUMBER(38,0) NOT NULL, XCOL1 SYS.XMLTYPE)
 XMLTYPE COLUMN XCOL1 STORE AS BASICFILE CLOB(TABLESPACE USERS ENABLE STORAGE IN ROW CHUNK 8192);

SQL> select * from bug_test1;
ERROR:
ORA-21500: internal error code, arguments: [%s], [%s], [%s], [%s], [%s], [%s],[%s], [%s]

we are using windows client here,but if you use UNIX then it throws more specific error.

SQL> select * from bug_test1;
Errors in file :
OCI-21500: internal error code, arguments: [qmcxdEvtNextPPP], [], [], [], [], [], [], []
Ð@ø0Ð@ø0Ð@ø0ERROR:
ORA-21500: internal error code, arguments: [%s], [%s], [%s], [%s], [%s], [%s],[%s], [%s]

This indeed tells us it’s an OCI error. But, how to trace this in windows. Well, this is what i learned from this error.


No OCI Trace Generated With 10.2 Oracle Client Using Oracle Data Provider for .Net [ID 1371240.1]

set ORA_CLIENTTRACE_DIR=c:\temp
set EVENT_10842=server=all;user=all;stmt=all;level=15

The following levels are supported:
1 - Trace all server attach and server detach calls for servers listed in "server" attribute of the environment variable.
2 - Trace all session begin, logon, session end, logoff calls for the users listed in "user" attribute of the environment variable.
3 - Trace all prepare, execute, fetch calls for the specified statement types listed in "stmt" attribute of environment variable.
4 - Trace all Bind, Define, Describe calls.
5 - Trace all OCI LOB calls
7 - Get statistical info on all connection pooling /connection related calls
8 - Get statistical info on all session info
9 - Get statistical info on all handle info
10 - Get statistical info on time taken in execute and fetch calls
11 - Get statistical info on transaction related calls
15 - Trace all calls with statistical info.

trcsess

This is a short note about trcsess. Basically used to combine multiple trace files into one using different criteria.


trcsess [output=<output file name >] [session=<session ID>] [clientid=<clientid>] [service=<service name>] [action=<action name>] [module=<module name>] <trace file names>

output=<output file name> output destination default being standard output.
session=<session Id> session to be traced.
Session id is a combination of session Index & session serial number e.g. 8.13.
clientid=<clientid> clientid to be traced.
service=<service name> service to be traced.
action=<action name> action to be traced.
module=<module name> module to be traced.
<trace_file_names> Space separated list of trace files with wild card '*' supported.

So, it clearly says that it can support separated list of trace file, but what if you want to combine using multiple service or action etc. I got one situation yesterday that some calls from application are coming from one service and that call end using some other service. Without combining this two trace file it was not possible to get whole picture. For example


*** 2012-07-17 17:07:30.379
*** SESSION ID:(XXX.XXXXX) 2012-07-17 17:07:30.379
*** CLIENT ID:() 2012-07-17 17:07:30.379
*** SERVICE NAME:(DATA_SERVICE) 2012-07-17 17:07:30.379
*** MODULE NAME:(YYYYY.exe) 2012-07-17 17:07:30.379
*** ACTION NAME:() 2012-07-17 17:07:30.379

*** 2012-07-17 16:33:07.734
*** SESSION ID:(XXX.XXXXX) 2012-07-17 16:33:07.734
*** CLIENT ID:() 2012-07-17 16:33:07.734
*** SERVICE NAME:(WEB_SERVICE) 2012-07-17 16:33:07.734
*** MODULE NAME:(ZZZZZ.exe) 2012-07-17 16:33:07.734
*** ACTION NAME:() 2012-07-17 16:33:07.734

I don’t know if there is some other way but what i did was

sed -i ‘s/ACTION NAME:()/ACTION NAME:(TARAL)/g’ *.trc

Then combine using action


*** 2012-07-17 17:07:30.379
*** SESSION ID:(XXX.XXXXX) 2012-07-17 17:07:30.379
*** CLIENT ID:() 2012-07-17 17:07:30.379
*** SERVICE NAME:(DATA_SERVICE) 2012-07-17 17:07:30.379
*** MODULE NAME:(YYYYY.exe) 2012-07-17 17:07:30.379
*** ACTION NAME:(TARAL) 2012-07-17 17:07:30.379

*** 2012-07-17 16:33:07.734
*** SESSION ID:(XXX.XXXXX) 2012-07-17 16:33:07.734
*** CLIENT ID:() 2012-07-17 16:33:07.734
*** SERVICE NAME:(WEB_SERVICE) 2012-07-17 16:33:07.734
*** MODULE NAME:(ZZZZZ.exe) 2012-07-17 16:33:07.734
*** ACTION NAME:(TARAL) 2012-07-17 16:33:07.734

ORA-00600 [kksgaGetNoAlloc_Int0]

We received this error for Interval/List partition. Here is the sample test case


drop table part_test purge;
CREATE TABLE PART_TEST (
 ID NUMBER,ST_CODE VARCHAR2(1),ST_DESC VARCHAR2(4000),
 CR_DATE date, INFO VARCHAR2(200)
 ) partition by range(ID) interval(1)
 SUBPARTITION BY LIST(ST_CODE)
 SUBPARTITION TEMPLATE
 (SUBPARTITION ST_CODE_a VALUES ('A'),
 SUBPARTITION ST_CODE_s VALUES ('S'),
 SUBPARTITION ST_CODE_v VALUES ('V'),
 SUBPARTITION ST_CODE_e VALUES ('E'),
 SUBPARTITION ST_CODE_oth VALUES (DEFAULT))
 (partition ID_1 values less than (111000));

TARAL.ORALINUX>select * from part_test where id=321000 and st_code='A';
select * from part_test where id=321000 and st_code='A'
 *
ERROR at line 1:
ORA-00600: internal error code, arguments: [kksgaGetNoAlloc_Int0], [1050005], [1048575], [], [], [], [], [], [], [], [], []

Now getting into details found that 1048575 number in that error is nothing but MAX number of allowed partitions in oracle. By the way test was done in 11.2.0.3. So, when we start partition with 111000 and add any partition it should consider one 1 list and 5 sub-partition. But, it’s considering a lot’s more and actually it’s a BUG. It calculate holes in that partition and not the  actual partitions. Here is little more details about that first argument in that error.


TARAL.ORALINUX>select ((321000-111000)*5)+5 from dual;

((321000-111000)*5)+5
---------------------
 1050005

So, it’s calculated partition value and which exceeds partition limit. That means it won’t track lowest created partition.

</pre>
TARAL.ORALINUX>select (1048570/5) + 111000 from dual;

(1048570/5)+111000
------------------
 320714

1 row selected.

TARAL.ORALINUX>select * from part_test where id=320714 and st_code='A';
select * from part_test where id=320714 and st_code='A'
 *
ERROR at line 1:
ORA-00600: internal error code, arguments: [kksgaGetNoAlloc_Int0], [1048575], [1048575], [], [], [], [], [], [], [], [], []

TARAL.ORALINUX>select * from part_test where id=320713 and st_code='A';

no rows selected
<pre>

By the way this is coming from CURSOR compilation itself i believe but not sure.  And here is the BUG

Bug 13722697  ORA-600 [kksgaGetNoAlloc_Int0] on select against composite interval partitioned table

Futex Spinning on CPU

Lately we had issue with SQL running for long and after investigating found that it was just hanging/spinning on CPU. Even there was no system stats that were increasing


    SID USERNAME    STATE   EVENT                                          SEQ# SEC_IN_STATE SQL_ID         CHN P1                        P2                        P3
------- ----------  ------- ---------------------------------------- ---------- ------------ ------------- ---- ------------------------- ------------------------- -----------------------
   1281 XXXXXXXXXXX WORKING On CPU / runqueue                             50039        12284 xxxxxxxxxxxxx    0 file#= 283                block#= 1702095           id#= 33554433
   1281 XXXXXXXXXXX WORKING On CPU / runqueue                             50039        12287 xxxxxxxxxxxxx    0 file#= 283                block#= 1702095           id#= 33554433
   1281 XXXXXXXXXXX WORKING On CPU / runqueue                             50039        12288 xxxxxxxxxxxxx    0 file#= 283                block#= 1702095           id#= 33554433
   1281 XXXXXXXXXXX WORKING On CPU / runqueue                             50039        12289 xxxxxxxxxxxxx    0 file#= 283                block#= 1702095           id#= 33554433
   1281 XXXXXXXXXXX WORKING On CPU / runqueue                             50039        12290 xxxxxxxxxxxxx    0 file#= 283                block#= 1702095           id#= 33554433
   1281 XXXXXXXXXXX WORKING On CPU / runqueue                             50039        12291 xxxxxxxxxxxxx    0 file#= 283                block#= 1702095           id#= 33554433
   1281 XXXXXXXXXXX WORKING On CPU / runqueue                             50039        12291 xxxxxxxxxxxxx    0 file#= 283                block#= 1702095           id#= 33554433
   1281 XXXXXXXXXXX WORKING On CPU / runqueue                             50039        12292 xxxxxxxxxxxxx    0 file#= 283                block#= 1702095           id#= 33554433
   1281 XXXXXXXXXXX WORKING On CPU / runqueue                             50039        12293 xxxxxxxxxxxxx    0 file#= 283                block#= 1702095           id#= 33554433

----------------------------------------------------------------------------------------------------------------------
    SID, USERNAME  , TYPE, STATISTIC                               ,         DELTA, HDELTA/SEC,    %TIME, GRAPH
----------------------------------------------------------------------------------------------------------------------
     -1,           , ENQG, AE - Edition Lock                       ,             3,         .3,
     -1,           , ENQG, CF - Controlfile Transaction            ,            20,          2,
     -1,           , ENQG, CO - KTUCLO Master Slave enq            ,             3,         .3,
     -1,           , ENQG, DD - ASM Local Disk Group               ,             4,         .4,
     -1,           , ENQG, JD - Job Queue Date                     ,             2,         .2,
     -1,           , ENQG, JS - Job Scheduler                      ,           316,       31.6,
     -1,           , ENQG, MR - Media Recovery                     ,             4,         .4,
     -1,           , ENQG, PS - PX Process Reservation             ,             9,         .9,
     -1,           , ENQG, SE - Session Migration                  ,             3,         .3,
     -1,           , ENQG, TM - DML                                ,            51,        5.1,
     -1,           , ENQG, TX - Transaction                        ,            13,        1.3,
     -1,           , ENQG, XR - Quiesce / Force Logging            ,             3,         .3,
     -1,           , LATG, post/wait queue                         ,            27,        2.7,
     -1,           , LATG, test excl. parent l0                    ,             2,         .2,
     -1,           , LATG, test excl. parent2 l0                   ,             2,         .2,
     -1,           , LATG, process allocation                      ,            59,        5.9,
     -1,           , LATG, session allocation                      ,            78,        7.8,
     -1,           , LATG, session switching                       ,             3,         .3,
     -1,           , LATG, process group creation                  ,             9,         .9,
     -1,           , LATG, session idle bit                        ,           141,       14.1,
     -1,           , LATG, client/application info                 ,            44,        4.4,
     -1,           , LATG, longop free list parent                 ,             2,         .2,
     -1,           , LATG, ksuosstats global area                  ,             1,         .1,
     -1,           , LATG, ksim membership request latch           ,             6,         .6,
     -1,           , LATG, kss move lock                           ,             2,         .2,
     -1,           , LATG, parameter table management              ,            15,        1.5,
     -1,           , LATG, messages                                ,           481,       48.1,
     -1,           , LATG, enqueues                                ,           713,       71.3,
     -1,           , LATG, enqueue hash chains                     ,           986,       98.6,
     -1,           , LATG, FOB s.o list latch                      ,             8,         .8,
     -1,           , LATG, ksfv messages                           ,             2,         .2,
     -1,           , LATG, msg queue latch                         ,             2,         .2,
     -1,           , LATG, done queue latch                        ,             2,         .2,
     -1,           , LATG, session queue latch                     ,             2,         .2,
     -1,           , LATG, resmgr:free threads list                ,            15,        1.5,
     -1,           , LATG, resmgr group change latch               ,             8,         .8,
     -1,           , LATG, channel handle pool latch               ,            11,        1.1,
     -1,           , LATG, channel operations parent latch         ,          1493,      149.3,
     -1,           , LATG, message pool operations parent latch    ,            30,          3,
     -1,           , LATG, ksv class latch                         ,            14,        1.4,
     -1,           , LATG, ksv msg queue latch                     ,             2,         .2,
     -1,           , LATG, ksv allocation latch                    ,             1,         .1,
     -1,           , LATG, second spare latch                      ,             2,         .2,
     -1,           , LATG, third spare latch                       ,             2,         .2,
     -1,           , LATG, fifth spare latch                       ,             2,         .2,
     -1,           , LATG, ksxp shared latch                       ,             9,         .9,
     -1,           , LATG, IPC stats buffer allocation latch       ,            59,        5.9,
     -1,           , LATG, granule operation                       ,             2,         .2,
     -1,           , LATG, active service list                     ,           104,       10.4,
     -1,           , LATG, OS process allocation                   ,            13,        1.3,
     -1,           , LATG, OS process                              ,            20,          2,
     -1,           , LATG, OS process: request allocation          ,             9,         .9,
     -1,           , LATG, ksz_so allocation latch                 ,             9,         .9,
     -1,           , LATG, ges process table freelist              ,             9,         .9,
     -1,           , LATG, ges process parent latch                ,           787,       78.7,
     -1,           , LATG, ges process hash list                   ,          1847,      184.7,
     -1,           , LATG, ges resource table freelist             ,            43,        4.3,
     -1,           , LATG, ges caches resource lists               ,           260,         26,
     -1,           , LATG, ges resource hash list                  ,           644,       64.4,
     -1,           , LATG, ges resource scan list                  ,             2,         .2,
     -1,           , LATG, ges enqueue table freelist              ,           393,       39.3,
     -1,           , LATG, ges timeout list                        ,             4,         .4,
     -1,           , LATG, KJC message pool free list              ,            24,        2.4,
     -1,           , LATG, KJCT flow control latch                 ,           362,       36.2,
     -1,           , LATG, ges domain table                        ,           379,       37.9,
     -1,           , LATG, ges group table                         ,           571,       57.1,
     -1,           , LATG, gcs resource hash                       ,           246,       24.6,
     -1,           , LATG, gcs opaque info freelist                ,            44,        4.4,
     -1,           , LATG, gcs resource freelist                   ,            20,          2,
     -1,           , LATG, gcs resource scan list                  ,             2,         .2,
     -1,           , LATG, gcs shadows freelist                    ,             8,         .8,
     -1,           , LATG, gcs commit scn state                    ,             2,         .2,
     -1,           , LATG, name-service request queue              ,           104,       10.4,
     -1,           , LATG, name-service pending queue              ,             4,         .4,
     -1,           , LATG, name-service namespace bucket           ,            63,        6.3,
     -1,           , LATG, name-service memory objects             ,            20,          2,
     -1,           , LATG, gcs partitioned table hash              ,         24776,      2.48k,
     -1,           , LATG, gcs pcm hashed value bucket hash        ,             2,         .2,
     -1,           , LATG, recovery domain hash list               ,             2,         .2,
     -1,           , LATG, ges value block free list               ,             2,         .2,
     -1,           , LATG, Testing                                 ,             2,         .2,
     -1,           , LATG, heartbeat check                         ,             5,         .5,
     -1,           , LATG, KMG MMAN ready and startup request latch,             4,         .4,
     -1,           , LATG, Memory Management Latch                 ,             6,         .6,
     -1,           , LATG, mostly latch-free SCN                   ,            20,          2,
     -1,           , LATG, lgwr LWN SCN                            ,            20,          2,
     -1,           , LATG, Consistent RBA                          ,            19,        1.9,
     -1,           , LATG, cache buffers lru chain                 ,           688,       68.8,
     -1,           , LATG, buffer pool                             ,             2,         .2,
     -1,           , LATG, active checkpoint queue latch           ,            24,        2.4,
     -1,           , LATG, checkpoint queue latch                  ,          1202,      120.2,
     -1,           , LATG, cache buffers chains                    ,          2012,      201.2,
     -1,           , LATG, cache buffer handles                    ,             8,         .8,
     -1,           , LATG, multiblock read objects                 ,            54,        5.4,
     -1,           , LATG, tablespace key chain                    ,            11,        1.1,
     -1,           , LATG, simulator lru latch                     ,            29,        2.9,
     -1,           , LATG, simulator hash latch                    ,            29,        2.9,
     -1,           , LATG, sim partition latch                     ,             2,         .2,
     -1,           , LATG, object queue header operation           ,          1998,      199.8,
     -1,           , LATG, object queue header heap                ,           291,       29.1,
     -1,           , LATG, archive control                         ,             1,         .1,
     -1,           , LATG, archive process latch                   ,             3,         .3,
     -1,           , LATG, redo writing                            ,            87,        8.7,
     -1,           , LATG, redo copy                               ,           149,       14.9,
     -1,           , LATG, redo allocation                         ,           208,       20.8,
     -1,           , LATG, gc element                              ,           582,       58.2,
     -1,           , LATG, logminer work area                      ,             2,         .2,
     -1,           , LATG, logminer context allocation             ,             2,         .2,
     -1,           , LATG, logical standby cache                   ,             2,         .2,
     -1,           , LATG, mapped buffers lru chain                ,             2,         .2,
     -1,           , LATG, lock DBA buffer during media recovery   ,             2,         .2,
     -1,           , LATG, flashback copy                          ,             2,         .2,
     -1,           , LATG, cvmap freelist lock                     ,             2,         .2,
     -1,           , LATG, io pool granule metadata list           ,             2,         .2,
     -1,           , LATG, dml lock allocation                     ,             1,         .1,
     -1,           , LATG, DML lock allocation                     ,           104,       10.4,
     -1,           , LATG, list of block allocation                ,             9,         .9,
     -1,           , LATG, transaction allocation                  ,            11,        1.1,
     -1,           , LATG, dummy allocation                        ,            17,        1.7,
     -1,           , LATG, transaction branch allocation           ,             8,         .8,
     -1,           , LATG, commit callback allocation              ,             4,         .4,
     -1,           , LATG, undo global data                        ,            46,        4.6,
     -1,           , LATG, corrupted undo seg lock                 ,             3,         .3,
     -1,           , LATG, MinActiveScn Latch                      ,           127,       12.7,
     -1,           , LATG, intra txn parallel recovery             ,             2,         .2,
     -1,           , LATG, In memory undo latch                    ,             2,         .2,
     -1,           , LATG, KTF sga latch                           ,             2,         .2,
     -1,           , LATG, Change Notification Hash table latch    ,             3,         .3,
     -1,           , LATG, change notification client cache latch  ,             2,         .2,
     -1,           , LATG, sort extent pool                        ,             1,         .1,
     -1,           , LATG, lob segment hash table latch            ,             2,         .2,
     -1,           , LATG, lob segment query latch                 ,             2,         .2,
     -1,           , LATG, lob segment dispenser latch             ,             2,         .2,
     -1,           , LATG, space background task latch             ,            13,        1.3,
     -1,           , LATG, sequence cache                          ,             9,         .9,
     -1,           , LATG, File State Object Pool Parent Latch     ,             2,         .2,
     -1,           , LATG, Write State Object Pool Parent Latch    ,             2,         .2,
     -1,           , LATG, deferred cleanup latch                  ,             1,         .1,
     -1,           , LATG, kdlx hb parent latch                    ,             2,         .2,
     -1,           , LATG, Locator state objects pool parent latch ,             2,         .2,
     -1,           , LATG, row cache objects                       ,           435,       43.5,
     -1,           , LATG, kks stats                               ,             2,         .2,
     -1,           , LATG, global KZLD latch for mem in SGA        ,             3,         .3,
     -1,           , LATG, user lock                               ,            18,        1.8,
     -1,           , LATG, global ctx hash table latch             ,            13,        1.3,
     -1,           , LATG, global tx hash mapping                  ,             2,         .2,
     -1,           , LATG, k2q lock allocation                     ,             2,         .2,
     -1,           , LATG, k2q global data latch                   ,             6,         .6,
     -1,           , LATG, shared pool                             ,           455,       45.5,
     -1,           , LATG, Token Manager                           ,             2,         .2,
     -1,           , LATG, cas latch                               ,             2,         .2,
     -1,           , LATG, rm cas latch                            ,             2,         .2,
     -1,           , LATG, resmgr:actses change state              ,             2,         .2,
     -1,           , LATG, resmgr:actses change group              ,             8,         .8,
     -1,           , LATG, resmgr:session queuing                  ,             2,         .2,
     -1,           , LATG, resmgr:active threads                   ,            15,        1.5,
     -1,           , LATG, resmgr:plan CPU method                  ,             2,         .2,
     -1,           , LATG, resmgr:resource group CPU method        ,             2,         .2,
     -1,           , LATG, QMT                                     ,             2,         .2,
     -1,           , LATG, shared pool simulator                   ,             2,         .2,
     -1,           , LATG, shared pool sim alloc                   ,             2,         .2,
     -1,           , LATG, Streams Generic                         ,             2,         .2,
     -1,           , LATG, Shared B-Tree                           ,             5,         .5,
     -1,           , LATG, Memory Queue                            ,             2,         .2,
     -1,           , LATG, Memory Queue Subscriber                 ,             2,         .2,
     -1,           , LATG, Memory Queue Message Subscriber #1      ,             2,         .2,
     -1,           , LATG, Memory Queue Message Subscriber #2      ,             2,         .2,
     -1,           , LATG, Memory Queue Message Subscriber #3      ,             2,         .2,
     -1,           , LATG, Memory Queue Message Subscriber #4      ,             2,         .2,
     -1,           , LATG, pesom_hash_node                         ,             2,         .2,
     -1,           , LATG, pesom_free_list                         ,             2,         .2,
     -1,           , LATG, peshm                                   ,             2,         .2,
     -1,           , LATG, Mutex                                   ,             2,         .2,
     -1,           , LATG, Mutex Stats                             ,             2,         .2,
     -1,           , LATG, KGNFS-NFS:SHM structure                 ,             2,         .2,
     -1,           , LATG, KGNFS-NFS:SVR LIST                      ,             2,         .2,
     -1,           , LATG, SGA heap locks                          ,             2,         .2,
     -1,           , LATG, SGA pool locks                          ,             2,         .2,
     -1,           , LATG, SGA bucket locks                        ,             2,         .2,
     -1,           , LATG, SGA blob parent                         ,             2,         .2,
     -1,           , LATG, kgb parent                              ,             2,         .2,
     -1,           , LATG, Event Group Locks                       ,             5,         .5,
     -1,           , LATG, session timer                           ,             8,         .8,
     -1,           , LATG, parameter list                          ,            97,        9.7,
     -1,           , LATG, virtual circuit buffers                 ,             2,         .2,
     -1,           , LATG, virtual circuit queues                  ,             2,         .2,
     -1,           , LATG, virtual circuit holder                  ,             2,         .2,
     -1,           , LATG, cp server hash latch                    ,             2,         .2,
     -1,           , LATG, cp pool latch                           ,             2,         .2,
     -1,           , LATG, cp cmon/server latch                    ,             2,         .2,
     -1,           , LATG, cp sga latch                            ,             1,         .1,
     -1,           , LATG, job_queue_processes parameter latch     ,             2,         .2,
     -1,           , LATG, job workq parent latch                  ,             2,         .2,
     -1,           , LATG, query server freelists                  ,            15,        1.5,
     -1,           , LATG, error message lists                     ,             5,         .5,
     -1,           , LATG, process queue                           ,            19,        1.9,
     -1,           , LATG, process queue reference                 ,           568,       56.8,
     -1,           , LATG, parallel query stats                    ,             8,         .8,
     -1,           , LATG, business card                           ,             4,         .4,
     -1,           , LATG, parallel query alloc buffer             ,            38,        3.8,
     -1,           , LATG, SQL memory manager latch                ,             3,         .3,
     -1,           , LATG, SQL memory manager workarea list latch  ,           215,       21.5,
     -1,           , LATG, compile environment latch               ,             6,         .6,
     -1,           , LATG, kokc descriptor allocation latch        ,             8,         .8,
     -1,           , LATG, ncodef allocation latch                 ,             1,         .1,
     -1,           , LATG, session state list latch                ,             6,         .6,
     -1,           , LATG, KWQS pqueue ctx latch                   ,             1,         .1,
     -1,           , LATG, KWQS pqsubs latch                       ,             1,         .1,
     -1,           , LATG, kwqbsn:qsga                             ,             1,         .1,
     -1,           , LATG, qmn task queue latch                    ,             4,         .4,
     -1,           , LATG, KWQMN job cache list latch              ,             3,         .3,
     -1,           , LATG, XDB unused session pool                 ,             2,         .2,
     -1,           , LATG, XDB used session pool                   ,             2,         .2,
     -1,           , LATG, XDB NFS Security Latch                  ,             2,         .2,
     -1,           , LATG, KFC Hash Latch                          ,             2,         .2,
     -1,           , LATG, KFC FX Hash Latch                       ,             2,         .2,
     -1,           , LATG, ASM map operation hash table            ,           186,       18.6,
     -1,           , LATG, ASM network background latch            ,             4,         .4,
     -1,           , LATG, ASM db client latch                     ,             6,         .6,
     -1,           , LATG, KFR redo allocation latch               ,             2,         .2,
     -1,           , LATG, KFCL LE Freelist                        ,             2,         .2,
     -1,           , LATG, JS broadcast add buf latch              ,             2,         .2,
     -1,           , LATG, JS broadcast drop buf latch             ,             2,         .2,
     -1,           , LATG, JS broadcast load blnc latch            ,             2,         .2,
     -1,           , LATG, JS slv state obj latch                  ,             2,         .2,
     -1,           , LATG, JS queue state obj latch                ,           312,       31.2,
     -1,           , LATG, JS queue access latch                   ,             2,         .2,
     -1,           , LATG, JS Sh mem access                        ,             4,         .4,
     -1,           , LATG, PL/SQL warning settings                 ,             9,         .9,
--  End of snap 1, end=2012-04-02 21:37:13, seconds=10

 CH# PARENT_HANDLE    OBJECT_HANDLE     PLAN_HASH     PARSES   H_PARSES EXECUTIONS    FETCHES ROWS_PROCESSED     CPU_MS     ELA_MS       LIOS       PIOS      SORTS USERS_EXECUTING
---- ---------------- ---------------- ---------- ---------- ---------- ---------- ---------- -------------- ---------- ---------- ---------- ---------- ---------- ---------------
   0 000000041CE5D250 000000041CE5D100 1758161767          1          1          0          0              0 154999.436 297611.236    8382945     707682          1               1

<-ksedsts()+315<-ksdxfstk()+32<-ksdxcb()+1764<-sspuser()+112<-__restore_rt()<-__lll_lock_wait_private()+30<-_L_lock_1685()+19<-ksmskgmctx_()<-00007FFF36F46508
<-ksedsts()+315<-ksdxfstk()+32<-ksdxcb()+1764<-sspuser()+112<-__restore_rt()<-__lll_lock_wait_private()+30<-_L_lock_1685()+19<-ksmskgmctx_()<-00007FFF36F46508
<-ksedsts()+315<-ksdxfstk()+32<-ksdxcb()+1764<-sspuser()+112<-__restore_rt()<-__lll_lock_wait_private()+30<-_L_lock_1685()+19<-ksmskgmctx_()<-00007FFF36F46508
<-ksedsts()+315<-ksdxfstk()+32<-ksdxcb()+1764<-sspuser()+112<-__restore_rt()<-__lll_lock_wait_private()+30<-_L_lock_1685()+19<-ksmskgmctx_()<-00007FFF36F46508
<-ksedsts()+315<-ksdxfstk()+32<-ksdxcb()+1764<-sspuser()+112<-__restore_rt()<-__lll_lock_wait_private()+30<-_L_lock_1685()+19<-ksmskgmctx_()<-00007FFF36F46508
<-ksedsts()+315<-ksdxfstk()+32<-ksdxcb()+1764<-sspuser()+112<-__restore_rt()<-__lll_lock_wait_private()+30<-_L_lock_1685()+19<-ksmskgmctx_()<-00007FFF36F46508
<-ksedsts()+315<-ksdxfstk()+32<-ksdxcb()+1764<-sspuser()+112<-__restore_rt()<-__lll_lock_wait_private()+30<-_L_lock_1685()+19<-ksmskgmctx_()<-00007FFF36F46508
<-ksedsts()+315<-ksdxfstk()+32<-ksdxcb()+1764<-sspuser()+112<-__restore_rt()<-__lll_lock_wait_private()+30<-_L_lock_1685()+19<-ksmskgmctx_()<-00007FFF36F46508
<-ksedsts()+315<-ksdxfstk()+32<-ksdxcb()+1764<-sspuser()+112<-__restore_rt()<-__lll_lock_wait_private()+30<-_L_lock_1685()+19<-ksmskgmctx_()<-00007FFF36F46508
<-ksedsts()+315<-ksdxfstk()+32<-ksdxcb()+1764<-sspuser()+112<-__restore_rt()<-__lll_lock_wait_private()+30<-_L_lock_1685()+19<-ksmskgmctx_()<-00007FFF36F46508

futex(0x3596554594, FUTEX_WAIT_PRIVATE, 2, NULL

#0  0x00000035962e027e in __lll_lock_wait_private () from /lib64/libc.so.6
#1  0x000000359628d56d in _L_lock_1685 () from /lib64/libc.so.6
#2  0x000000359628d2b7 in __tz_convert () from /lib64/libc.so.6
#3  0x0000000001db392a in sldxgd ()
#4  0x000000000339ddfd in nldatxtmil ()
#5  0x000000000339dd20 in nldatxt ()
#6  0x00000000076c6135 in nstimexp ()
#7  0x00000000064c1bca in ltmdvp ()
#8  0x00000000064c1ae3 in ltmdrv ()
#9  0x00000000064a6fc0 in sltmdf ()
#10 0x0000000006496325 in sslsstehdlr ()
#11 0x00000000064957e9 in sslsshandler ()
#12 <signal handler called>
#13 0x000000359628d88f in __tzfile_compute () from /lib64/libc.so.6
#14 0x000000359628d2ef in __tz_convert () from /lib64/libc.so.6
#15 0x0000000007ccdbb2 in sLdiGetDate ()
#16 0x00000000019104b7 in psdsts ()
#17 0x0000000002b0ffe4 in pessts ()
#18 0x0000000007dd6fae in pevm_icd_call_common ()
#19 0x0000000007dce9c3 in pfrinstr_BCAL ()
#20 0x0000000007dcdc3f in pfrrun_no_tool ()
#21 0x0000000002a276e7 in pfrrun ()
#22 0x0000000002a38c7d in plsql_run ()
#23 0x0000000002a1ebc4 in peicnt ()
#24 0x0000000002a1ea0d in peiet_execute_trigger ()
#25 0x00000000023f8080 in kkxtexe ()
#26 0x00000000019437dc in kxtExecuteTriggerRecursive ()
#27 0x0000000007c1267a in rpiswu2 ()
#28 0x0000000001942f66 in kxtExecuteTriggerReal ()
#29 0x0000000001942d3f in kxtexe ()
#30 0x0000000001cc468e in qesltcExecuteBeforeRowTriggers ()
#31 0x0000000007cacc8b in qesltcBeforeRowProcessing ()
#32 0x0000000007c8c9a3 in __PGOSF606_qerltcKdtBufferedInsRowCBK ()
#33 0x0000000007c8c47e in qerltcLoadStateMachine ()
#34 0x0000000007c8bf9d in __PGOSF596_qerltcInsertSelectRop ()
#35 0x0000000001c8d868 in qerghFetch ()
#36 0x0000000007afa0a9 in rwsfcd ()
#37 0x0000000007c8a447 in qerltcFetch ()
#38 0x0000000007bd5a1d in insexe ()
#39 0x0000000007c9bfe7 in opiexe ()
#40 0x0000000001cd1dc5 in kpoal8 ()
#41 0x0000000007b4e0d4 in opiodr ()
#42 0x0000000007d0ea8b in ttcpip ()
#43 0x000000000106800d in opitsk ()
#44 0x000000000106aa2a in opiino ()
#45 0x0000000007b4e0d4 in opiodr ()
#46 0x0000000001063d6c in opidrv ()
#47 0x000000000177d4c2 in sou2o ()
#48 0x0000000000975603 in opimai_real ()
#49 0x0000000001782a79 in ssthrdmain ()
#50 0x000000000097552f in main ()

This is from metalink.

Bug 6918493 – Net DCD (sqlnet.expire_time>0) can cause OS level mutex hang, possible to get PMON failed to acquired latch

Using Net dead connection detection (DCD) by setting SQLNET.EXPIRE_TIME > 0 in the SQLNET.ORA file can cause an OS level mutex hang under nsexptim -> … -> localtime_r .. and possibly under other substacks under nsexptim . The hang is very intermittent in nature as it depends on a specific timing scenario.

If the hung process is holding a critical resource, such as a latch, then this can lead to a wider hang scenario.

Rediscovery Notes:
Dead Connection Detection is enabled (SQLNET.EXPIRE_TIME > 0 )
The stack includes nsexptim and is likely to include
localtime_tz_r or localtime_r
The top of the stack shows the session blocked on an
OS mutex. (eg: In __lll_mutex_lock_wait on Linux, or in a
futex call)
If the hung process holds a latch, or other critical
resource, then PMON may give a clue in its tracefile.

Workaround:
Disable DCD and configure OS level keepalive instead.
eg: Set SQLNET.EXPIRE_TIME=0 in the SQLNET.ORA file
and configure TCP keepalive to the required timeouts
at OS level (exact parameters and steps vary between
platforms as TCP keepalive is an OS level configuration)

ORA-12539: TNS:buffer over- or under-flow

This error was recived due to big NSPTCN packet size. I think this is a bug we have 11.1.0.7 Client. When NSPTRD packet is bigger than a NSPTCN packet and If NSPTRD packet size is over 532 byte, client received ORA-12539.

In our case PROGRAM was using big path and once it was shorten it got resolved. Here in trace I had removed/replaced some parts.


(47200) [000003 16-MAR-2012 13:40:09:063] nspsend: plen=414, type=6
(47200) [000003 16-MAR-2012 13:40:09:063] nttwr: entry
(47200) [000003 16-MAR-2012 13:40:09:063] nttwr: socket 2392 had bytes written=414
(47200) [000003 16-MAR-2012 13:40:09:063] nttwr: exit
(47200) [000003 16-MAR-2012 13:40:09:063] nspsend: packet dump
(47200) [000003 16-MAR-2012 13:40:09:063] nspsend: 01 9E 00 00 06 00 00 00  |........|
(47200) [000003 16-MAR-2012 13:40:09:063] nspsend: 00 00 28 44 45 53 43 52  |..(DESCR|
(47200) [000003 16-MAR-2012 13:40:09:063] nspsend: 49 50 54 49 4F 4E 3D 28  |IPTION=(|
(47200) [000003 16-MAR-2012 13:40:09:063] nspsend: 41 44 44 52 45 53 53 3D  |ADDRESS=|
(47200) [000003 16-MAR-2012 13:40:09:063] nspsend: 28 50 52 4F 54 4F 43 4F  |(PROTOCO|
(47200) [000003 16-MAR-2012 13:40:09:063] nspsend: 4C 3D 54 43 50 29 28 48  |L=TCP)(H|
(47200) [000003 16-MAR-2012 13:40:09:063] nspsend: 4F 53 54 3D 75 74 78 67  |OST=XXXX|
(47200) [000003 16-MAR-2012 13:40:09:063] nspsend: 72 61 6E 72 61 63 75 30  |XXXXXXXX|
(47200) [000003 16-MAR-2012 13:40:09:064] nspsend: 34 2D 76 69 70 2E 74 78  |XXXXXXXX|
(47200) [000003 16-MAR-2012 13:40:09:064] nspsend: 2E 65 70 73 69 6C 6F 6E  |XXXXXXXX|
(47200) [000003 16-MAR-2012 13:40:09:064] nspsend: 2E 63 6F 6D 29 28 50 4F  |XXXX)(PO|
(47200) [000003 16-MAR-2012 13:40:09:064] nspsend: 52 54 3D 31 35 32 32 29  |RT=XXXX)|
(47200) [000003 16-MAR-2012 13:40:09:064] nspsend: 29 28 4C 4F 41 44 5F 42  |)(LOAD_B|
(47200) [000003 16-MAR-2012 13:40:09:064] nspsend: 41 4C 41 4E 43 45 3D 79  |ALANCE=y|
(47200) [000003 16-MAR-2012 13:40:09:064] nspsend: 65 73 29 28 43 4F 4E 4E  |es)(CONN|
(47200) [000003 16-MAR-2012 13:40:09:064] nspsend: 45 43 54 5F 44 41 54 41  |ECT_DATA|
(47200) [000003 16-MAR-2012 13:40:09:064] nspsend: 3D 28 53 45 52 56 45 52  |=(SERVER|
(47200) [000003 16-MAR-2012 13:40:09:064] nspsend: 3D 44 45 44 49 43 41 54  |=DEDICAT|
(47200) [000003 16-MAR-2012 13:40:09:064] nspsend: 45 44 29 28 53 45 52 56  |ED)(SERV|
(47200) [000003 16-MAR-2012 13:40:09:064] nspsend: 49 43 45 5F 4E 41 4D 45  |ICE_NAME|
(47200) [000003 16-MAR-2012 13:40:09:064] nspsend: 3D 55 31 47 52 41 4E 5F  |=XXXXXXX|
(47200) [000003 16-MAR-2012 13:40:09:064] nspsend: 47 43 5F 53 45 52 56 49  |XXXXXXXX|
(47200) [000003 16-MAR-2012 13:40:09:064] nspsend: 43 45 29 28 46 41 49 4C  |XX)(FAIL|
(47200) [000003 16-MAR-2012 13:40:09:064] nspsend: 4F 56 45 52 5F 4D 4F 44  |OVER_MOD|
(47200) [000003 16-MAR-2012 13:40:09:064] nspsend: 45 3D 28 54 59 50 45 3D  |E=(TYPE=|
(47200) [000003 16-MAR-2012 13:40:09:064] nspsend: 53 45 4C 45 43 54 29 28  |SELECT)(|
(47200) [000003 16-MAR-2012 13:40:09:064] nspsend: 4D 45 54 48 4F 44 3D 42  |METHOD=B|
(47200) [000003 16-MAR-2012 13:40:09:064] nspsend: 41 53 49 43 29 28 52 45  |ASIC)(RE|
(47200) [000003 16-MAR-2012 13:40:09:064] nspsend: 54 52 49 45 53 3D 33 30  |TRIES=30|
(47200) [000003 16-MAR-2012 13:40:09:064] nspsend: 29 28 44 45 4C 41 59 3D  |)(DELAY=|
(47200) [000003 16-MAR-2012 13:40:09:064] nspsend: 35 29 29 28 43 49 44 3D  |5))(CID=|
(47200) [000003 16-MAR-2012 13:40:09:064] nspsend: 28 50 52 4F 47 52 41 4D  |(PROGRAM|
(47200) [000003 16-MAR-2012 13:40:09:064] nspsend: 3D 43 3A 5C 53 4D 61 6E  |=XXXXXXX|
(47200) [000003 16-MAR-2012 13:40:09:064] nspsend: 64 69 67 61 5C 73 72 63  |XXXXXXXX|
(47200) [000003 16-MAR-2012 13:40:09:064] nspsend: 5C 47 72 61 6E 64 43 65  |XXXXXXXX|
(47200) [000003 16-MAR-2012 13:40:09:064] nspsend: 6E 74 72 61 6C 5C 47 43  |XXXXXXXX|
(47200) [000003 16-MAR-2012 13:40:09:064] nspsend: 5F 52 6F 6F 74 5C 44 65  |XXXXXXXX|
(47200) [000003 16-MAR-2012 13:40:09:064] nspsend: 76 5C 50 43 6F 6E 66 69  |XXXXXXXX|
(47200) [000003 16-MAR-2012 13:40:09:064] nspsend: 67 5F 76 4E 65 78 74 5C  |XXXXXXXX|
(47200) [000003 16-MAR-2012 13:40:09:064] nspsend: 42 61 74 63 68 5C 41 75  |XXXXXXXX|
(47200) [000003 16-MAR-2012 13:40:09:064] nspsend: 74 6F 42 61 74 63 68 50  |XXXXXXXX|
(47200) [000003 16-MAR-2012 13:40:09:064] nspsend: 72 6F 63 65 73 73 6F 72  |XXXXXXXX|
(47200) [000003 16-MAR-2012 13:40:09:064] nspsend: 5C 62 69 6E 5C 44 65 62  |XXXXXXXX|
(47200) [000003 16-MAR-2012 13:40:09:064] nspsend: 75 67 5C 41 75 74 6F 42  |XXXXXXXX|
(47200) [000003 16-MAR-2012 13:40:09:064] nspsend: 61 74 63 68 50 72 6F 63  |XXXXXXXX|
(47200) [000003 16-MAR-2012 13:40:09:064] nspsend: 65 73 73 6F 72 2E 76 73  |XXXXXXXX|
(47200) [000003 16-MAR-2012 13:40:09:064] nspsend: 68 6F 73 74 2E 65 78 65  |XXXXXXXX|
(47200) [000003 16-MAR-2012 13:40:09:064] nspsend: 29 28 48 4F 53 54 3D 57  |)(HOST=X|
(47200) [000003 16-MAR-2012 13:40:09:064] nspsend: 54 58 45 50 53 49 44 45  |XXXXXXXX|
(47200) [000003 16-MAR-2012 13:40:09:064] nspsend: 56 34 36 29 28 55 53 45  |XXX)(USE|
(47200) [000003 16-MAR-2012 13:40:09:064] nspsend: 52 3D 73 6D 61 6E 64 69  |R=yyyyyy|
(47200) [000003 16-MAR-2012 13:40:09:064] nspsend: 67 61 29 29 29 29        |yy))))  |
(47200) [000003 16-MAR-2012 13:40:09:064] nspsend: 414 bytes to transport
(47200) [000003 16-MAR-2012 13:40:09:064] nspsend: normal exit
(47200) [000003 16-MAR-2012 13:40:09:064] nsdofls: exit (0)
(47200) [000003 16-MAR-2012 13:40:09:064] nsdoacts: flushing transport
(47200) [000003 16-MAR-2012 13:40:09:064] nttctl: entry
(47200) [000003 16-MAR-2012 13:40:09:064] nsdoacts: normal exit
(47200) [000003 16-MAR-2012 13:40:09:064] nsdo: normal exit
(47200) [000003 16-MAR-2012 13:40:09:064] nscon: exit (0)
(47200) [000003 16-MAR-2012 13:40:09:064] snsbitts_ts: entry
(47200) [000003 16-MAR-2012 13:40:09:064] snsbitts_ts: acquired the bit
(47200) [000003 16-MAR-2012 13:40:09:064] snsbitts_ts: normal exit
(47200) [000003 16-MAR-2012 13:40:09:064] nsdo: nsctxrnk=0
(47200) [000003 16-MAR-2012 13:40:09:064] snsbitcl_ts: entry
(47200) [000003 16-MAR-2012 13:40:09:064] snsbitcl_ts: normal exit
(47200) [000003 16-MAR-2012 13:40:09:064] nsdo: normal exit
(47200) [000003 16-MAR-2012 13:40:09:064] nsdo: entry
(47200) [000003 16-MAR-2012 13:40:09:064] nsdo: cid=0, opcode=68, *bl=512, *what=9, uflgs=0x0, cflgs=0x3
(47200) [000003 16-MAR-2012 13:40:09:064] snsbitts_ts: entry
(47200) [000003 16-MAR-2012 13:40:09:064] snsbitts_ts: acquired the bit
(47200) [000003 16-MAR-2012 13:40:09:064] snsbitts_ts: normal exit
(47200) [000003 16-MAR-2012 13:40:09:064] nsdo: rank=64, nsctxrnk=0
(47200) [000003 16-MAR-2012 13:40:09:064] snsbitcl_ts: entry
(47200) [000003 16-MAR-2012 13:40:09:064] snsbitcl_ts: normal exit
(47200) [000003 16-MAR-2012 13:40:09:064] nsdo: nsctx: state=2, flg=0x4005, mvd=0
(47200) [000003 16-MAR-2012 13:40:09:064] nsdo: gtn=10, gtc=10, ptn=10, ptc=8155
(47200) [000003 16-MAR-2012 13:40:09:064] nscon: entry
(47200) [000003 16-MAR-2012 13:40:09:064] nscon: recving a packet
(47200) [000003 16-MAR-2012 13:40:09:064] nsprecv: entry
(47200) [000003 16-MAR-2012 13:40:09:064] nsprecv: reading from transport...
(47200) [000003 16-MAR-2012 13:40:09:064] nttrd: entry
(47200) [000003 16-MAR-2012 13:40:09:064] nttrd: socket 2392 had bytes read=536
(47200) [000003 16-MAR-2012 13:40:09:064] nttrd: exit
(47200) [000003 16-MAR-2012 13:40:09:064] nsprecv: 536 bytes from transport
(47200) [000003 16-MAR-2012 13:40:09:064] nsprecv: tlen=536, plen=10, type=5
(47200) [000003 16-MAR-2012 13:40:09:064] nsprecv: 526 bytes to leftover
(47200) [000003 16-MAR-2012 13:40:09:064] nsprecv: packet dump
(47200) [000003 16-MAR-2012 13:40:09:064] nsprecv: 00 0A 00 00 05 02 00 00  |........|
(47200) [000003 16-MAR-2012 13:40:09:064] nsprecv: 02 04                    |..      |
(47200) [000003 16-MAR-2012 13:40:09:064] nsprecv: normal exit
(47200) [000003 16-MAR-2012 13:40:09:064] nscon: got NSPTRD packet
(47200) [000003 16-MAR-2012 13:40:09:064] nscon: connect data overflow
(47200) [000003 16-MAR-2012 13:40:09:064] nserror: entry
(47200) [000003 16-MAR-2012 13:40:09:064] nserror: nsres: id=0, op=77, ns=12539, ns2=0; nt[0]=0, nt[1]=0, nt[2]=0; ora[0]=0, ora[1]=0, ora[2]=0
(47200) [000003 16-MAR-2012 13:40:09:064] nscon: error exit
(47200) [000003 16-MAR-2012 13:40:09:064] snsbitts_ts: entry
(47200) [000003 16-MAR-2012 13:40:09:064] snsbitts_ts: acquired the bit
(47200) [000003 16-MAR-2012 13:40:09:064] snsbitts_ts: normal exit
(47200) [000003 16-MAR-2012 13:40:09:064] nsdo: nsctxrnk=0
(47200) [000003 16-MAR-2012 13:40:09:064] snsbitcl_ts: entry
(47200) [000003 16-MAR-2012 13:40:09:064] snsbitcl_ts: normal exit
(47200) [000003 16-MAR-2012 13:40:09:064] nsdo: error exit