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
Advertisements

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

ERROR: Emon failed to start

A short note on this error which popup in alertlog. This was due to session were waiting for


select inst_id,sid, serial#, event from gv$session where upper(event) like upper('%wait for EMON to spawn%');

   INST_ID        SID    SERIAL# EVENT
---------- ---------- ---------- ----------------------------------------------------------------
         2       1428        259 wait for EMON to spawn
         1       1388         32 wait for EMON to spawn

And as per metalink note 1361166.1 there are numerous entries on system table sys.reg$. Also, that document refer to some oracle bugs also. ID 782050.1

SQL> select SUBSCRIPTION_NAME ,count(*) from reg$ group by SUBSCRIPTION_NAME;

SUBSCRIPTION_NAME
--------------------------------------------------------------------------------   COUNT(*)
----------
"SYS"."ALERT_QUE":"HAE_SUB"
         3

"SYS"."SRVQUEUE":"TAFTSM"
      8992

Removing the excessive entries from sys.reg$ will resolve the EMON start-up issue

SQL> delete from sys.reg$ where location_name like 'net8%' and
	location_name not in (select location_name from sys.loc$) and subscription_name like '%TAFTSM%';

8987 rows deleted.

SQL> commit;

Commit complete.

SQL> select SUBSCRIPTION_NAME ,count(*) from reg$ group by SUBSCRIPTION_NAME;

SUBSCRIPTION_NAME
--------------------------------------------------------------------------------
  COUNT(*)
----------
"SYS"."ALERT_QUE":"HAE_SUB"
         3

"SYS"."SRVQUEUE":"TAFTSM"
         5

Adding Column In 11g With Default Values

Few days back friend ask me in 10g or previous version adding column in existing table with default values with not null constraint takes longer time while in 11g it takes few seconds.

Well, Answer to this is to test. Starting with 10.2.0.5 then 11g


10.2.0.5
=============

create table test as select rownum col1, 'XX' col2 from dual connect by level <= 20000;

Table created.

Elapsed: 00:00:00.09
alter table test add (col3 varchar2(10) default 'YYYY' not null);

Table altered.

Elapsed: 00:00:01.31

11.2.0.3
=============

create table test as select rownum col1, 'XX' col2 from dual connect by level <= 20000;

Table created.

Elapsed: 00:00:00.14
alter table test add (col3 varchar2(10) default 'YYYY' not null);

Table altered.

Elapsed: 00:00:00.01

Well, it’s a good amount of difference. Reason behind this is before 11g when you add column with default values and not null constraint it has to update all the columns in that tables which are null.

Starting from 11g this has changed. In 11g oracle keeps the information in the dictionary table ecol$. So, when you add column there are just few data dictonary operations. And when you select from that table it find that information from that table to populate values for existing data. But, when you insert new record it insert it with that values as default. It keeps track of that. Also, while doing this operation it takes “ROW EXCLUSIVE MODE NOWAIT” Lock.

Here is the example.


drop table test purge;
create table test pctfree 99 as select rownum col1, 'XX' col2 from dual connect by level <= 10;

tl: 9 fb: --H-FL-- lb: 0x0  cc: 2
col  0: [ 2]  c1 0a
col  1: [ 2]  58 58
tab 0, row 3, @0x1f5c
tl: 9 fb: --H-FL-- lb: 0x0  cc: 2
col  0: [ 2]  c1 0b
col  1: [ 2]  58 58

select * from test;

      COL1 CO COL3
---------- -- ----------
         1 XX YYYY
         2 XX YYYY
         3 XX YYYY
         4 XX YYYY
         5 XX YYYY
         6 XX YYYY
         7 XX YYYY
         8 XX YYYY
         9 XX YYYY
        10 XX YYYY

select utl_raw.cast_to_varchar2(dbms_lob.substr(BINARYDEFVAL)) from sys.ecol$;

UTL_RAW
---------
YYYY

Now, when you insert a row.

insert into test values(11,'XX','AAAA');

tl: 14 fb: --H-FL-- lb: 0x1  cc: 3
col  0: [ 2]  c1 0c
col  1: [ 2]  58 58
col  2: [ 4]  41 41 41 41

Also, do disable this feature you can set _add_col_optim_enabled to false and you are back to 10g like behaviour.

ORA-03137 TTC protocol internal error

Recently received this error on one of our 11.1.0.7 Database. Here is the description from alert log


Errors in file /...../1.trc:
ORA-03137: TTC protocol internal error : [12333] [5] [196] [2] [] [] [] []
----- Error Stack Dump -----
ORA-03137: TTC protocol internal error : [12333] [5] [196] [2] [] [] [] []
----- Current SQL Statement for this session (sql_id=xyzxxxxxxxxxxx) -----
UPDATE test stage_table SET ..... :BIND1 ... :BIND2 ... :BIND3 ........

Well, so what does it mean. After further investigation it’s a bug regarding bind peeking.

Here is what oracle workaround for same.

Bug 8625762 ORA-3137 [12333] due to bind data not read from wire

eg: Typically the trace file will show a PROTOCOL VIOLATION with Page before data showing a SQL statement (or request to execute a statement), the last 3 bytes of which are a bind length and the start of bind data, and then will show “Current Page” with the rest of thebind data.

Workaround
Setting “_optim_peek_user_binds”=false avoids this problem but use this with caution as it can affect execution plans chosen by CBO.

Not so clear. Let’s look into some details. First part of trace


--- PROTOCOL VIOLATION DETECTED ---
----- Dump Cursor sql_id=xyzxxxxxxxxxxx xsc=0x2b99f42bc148 cur=0x2b99f3d01d40 -----
Dump Parent Cursor sql_id=xyzxxxxxxxxxxx phd=0xcccccccc plk=0xyyyyyyyyy
 sqltxt(0xcccccccc)=UPDATE test stage_table SET ..... :BIND1 ... :BIND2 ... :BIND3 ........
  hash=xxxxxxxxxxxxx
  parent=0xYYYYYY maxchild=07 plk=0xyyyyyyyyy ppn=n
.......................
.......................
.......................

  sharing failure(s)=800000040000
----- Bind Info (kkscoacd) -----
 Bind#0
  oacdty=02 mxl=22(21) mxlc=00 mal=00 scl=00 pre=00
  oacflg=03 fl2=1000000 frm=00 csi=00 siz=2096 off=0
  kxsbbbfp=2b99f4241e10  bln=22  avl=00  flg=05
 Bind#1
  oacdty=01 mxl=2000(132) mxlc=33 mal=00 scl=00 pre=00
  oacflg=03 fl2=1000010 frm=01 csi=873 siz=0 off=24
  kxsbbbfp=2b99f4241e28  bln=2000  avl=00  flg=01
 Bind#2
  oacdty=02 mxl=22(21) mxlc=00 mal=00 scl=00 pre=00
  oacflg=03 fl2=1000000 frm=00 csi=00 siz=0 off=2024
  kxsbbbfp=2b99f42425f8  bln=22  avl=00  flg=01
 Bind#3
  oacdty=02 mxl=22(21) mxlc=00 mal=00 scl=00 pre=00
  oacflg=03 fl2=1000000 frm=00 csi=00 siz=0 off=2048
  kxsbbbfp=2b99f4242610  bln=22  avl=00  flg=01
 Bind#4
  oacdty=02 mxl=22(21) mxlc=00 mal=00 scl=00 pre=00
  oacflg=03 fl2=1000000 frm=00 csi=00 siz=0 off=2072
  kxsbbbfp=2b99f4242628  bln=22  avl=00  flg=01
 Frames pfr 0x2b99f40af0b0 siz=20744 efr 0x2b99f40aefd8 siz=20720
 kxscphp=0x2b99f4633808 siz=1992 inu=1616 nps=1504
 kxscbhp=0x2b99f4633e98 siz=3104 inu=2368 nps=2120
Starting SQL statement dump

As, you can see from this avl=00 so bind length is Zero and sharing failure(s)=800000040000 which corrospond to USER_BIND_PEEK_MISMATCH + BIND_EQUIV_FAILURE. So, this is related to bind peeking.

Further there is an another section in trace that is


-----Page before-----
XXXXXXXXX 03 5E 19 29 80 00 00 00 00 00 00 01 CC 03 00 00  [.^.)............]
XXXXXXXXX 01 0D 00 00 00 01 01 00 00 00 00 01 00 00 00 00  [................]
..................................
..................................
..................................
..................................
..................................
XXXXXXXXX 00 00 00 00 00 00 00 00 00 00 02 03 00 00 15 00  [................]
XXXXXXXXX 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00  [................]
XXXXXXXXX 00 00 00 00 00 00 00 07 05 C4 02                 [...........]
-----Current Page-----
nsbfdbpt 0x1b74mmmm
ifccrcp = 0x1b74mmm, ifccrcl = 0x1b74emmm
buffer length = 56
XXXXXXXXX                                  01 02 1C 21 54             [...!T]
..................................
..................................
XXXXXXXXX 04 C3 47 51 57 06 C5 04 41 64 58 51 06 C5 04 42  [..GQW...AdXQ...B]
XXXXXXXXX 01 58 51                                         [.XQ]

03 5E – The Page before shows we have an OALL8 packet and it looks like bind data has been left on the wire. As you can see last three bytes of bind data is left and read as new packet also they matches our error.

Also, in that last three bytes length of first bind data is 5 second is 21 and so on.

I have change some names of files and other stuff but data which i want to show are same from trace.