ORA-21500 Bug for 11gR1 Client Using XMLTYPE
April 28, 2013
Leave a comment
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.
Categories: Internal, Troubleshooting
trcsess
July 18, 2012
Leave a comment
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
Categories: Utilities
ORA-00600 [kksgaGetNoAlloc_Int0]
July 3, 2012
Leave a comment
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
Categories: Internal, Troubleshooting
Futex Spinning on CPU
April 9, 2012
Leave a comment
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)
Categories: Troubleshooting
ORA-12539: TNS:buffer over- or under-flow
March 27, 2012
2 comments
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
Categories: Network
ERROR: Emon failed to start
February 28, 2012
Leave a comment
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
Categories: Troubleshooting
Adding Column In 11g With Default Values
February 17, 2012
4 comments
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.
Categories: Troubleshooting
