首页 » ORACLE 9i-23ai » Troubleshooting Internal error ora-600 [kxspoac : EXL 1] after enable 10503 event
Troubleshooting Internal error ora-600 [kxspoac : EXL 1] after enable 10503 event
简单记录一下这个内部错误 ora-600 [kxspoac : EXL 1], 环境11.2.0.3 RAC on hpux ia, 这是一个并行查询相关的错误，当启了10503 event后并行查询带绑定变量的SQL时有可能会出现此错误。
adrci> show incident -all 1152791 ORA 600 [kxspoac : EXL 1] 2019-03-24 23:24:41.335000 +08:00 1152792 ORA 600 [kxspoac : EXL 1] 2019-03-24 23:54:49.425000 +08:00 1152793 ORA 600 [kxspoac : EXL 1] 2019-03-25 00:56:05.332000 +08:00 1152794 ORA 600 [kxspoac : EXL 1] 2019-03-25 01:16:09.069000 +08:00 1152795 ORA 600 [kxspoac : EXL 1] 2019-03-25 02:36:20.385000 +08:00 1152796 ORA 600 [kxspoac : EXL 1] 2019-03-25 02:46:22.276000 +08:00 1152797 ORA 600 [kxspoac : EXL 1] 2019-03-25 02:56:24.033000 +08:00 1200492 ORA 600 [kxspoac : EXL 1] 2019-03-25 03:06:25.915000 +08:00 1159670 ORA 600 [kxspoac : EXL 1] 2019-03-25 03:16:27.571000 +08:00 1159671 ORA 600 [kxspoac : EXL 1] 2019-03-25 05:46:56.464000 +08:00 1159672 ORA 600 [kxspoac : EXL 1] 2019-03-25 05:56:58.675000 +08:00 1159673 ORA 600 [kxspoac : EXL 1] 2019-03-25 06:08:01.796000 +08:00 adrci> show incident -mode detail -p "incident_id=1159673" ADR Home = /oracle/app/oracle/diag/rdbms/anbob/anbob1: ************************************************************************* ********************************************************** INCIDENT INFO RECORD 1 ********************************************************** INCIDENT_ID 1159673 STATUS ready CREATE_TIME 2019-03-25 06:08:01.796000 +08:00 PROBLEM_ID 8 CLOSE_TIME <NULL> FLOOD_CONTROLLED none ERROR_FACILITY ORA ERROR_NUMBER 600 ERROR_ARG1 kxspoac : EXL 1 ERROR_ARG2 2000 ERROR_ARG3 32 ERROR_ARG4 <NULL> ERROR_ARG5 <NULL> ERROR_ARG6 <NULL> ERROR_ARG7 <NULL> ERROR_ARG8 <NULL> ERROR_ARG9 <NULL> ERROR_ARG10 <NULL> ERROR_ARG11 <NULL> ERROR_ARG12 <NULL> SIGNALLING_COMPONENT cursor SIGNALLING_SUBCOMPONENT <NULL> SUSPECT_COMPONENT <NULL> SUSPECT_SUBCOMPONENT <NULL> ECID <NULL> IMPACTS 0 PROBLEM_KEY ORA 600 [kxspoac : EXL 1] FIRST_INCIDENT 1152270 FIRSTINC_TIME 2019-03-20 09:56:07.223000 +08:00 LAST_INCIDENT 1200518 LASTINC_TIME 2019-03-25 11:18:57.553000 +08:00 IMPACT1 0 IMPACT2 0 IMPACT3 0 IMPACT4 0 KEY_NAME PQ KEY_VALUE (33571929, 1553465280) KEY_NAME SID KEY_VALUE 8225.5665 KEY_NAME ProcId KEY_VALUE 957.47 KEY_NAME Client ProcId KEY_VALUE oracle@qdtza1.14635_1 OWNER_ID 1 INCIDENT_FILE /oracle/app/oracle/diag/rdbms/anbob/anbob1/incident/incdir_1159673/anbob1_pz99_14635_i1159673.trc OWNER_ID 1 INCIDENT_FILE /oracle/app/oracle/diag/rdbms/anbob/anbob1/trace/anbob1_pz99_14635.trc OWNER_ID 1 INCIDENT_FILE /oracle/app/oracle/diag/rdbms/anbob/anbob1/incident/incdir_1159673/anbob1_m000_10497_i1159673_a.trc ADR Home = /oracle/app/oracle/diag/clients/user_oracle/host_454940151_80: ************************************************************************* 0 rows fetched </ADR_HOME> <ADR_HOME name="/oracle/app/oracle/diag/clients/user_oracle/host_454940151_80"> ADR Home = /oracle/app/oracle/diag/tnslsnr/qdtza1/listener_gj: ************************************************************************* 0 rows fetched adrci> show trace /oracle/app/oracle/diag/rdbms/anbob/anbob1/incident/incdir_1159673/anbob1_pz99_14635_i1159673.trc Output the results to file: /tmp/utsout_2836_1_2.ado "/tmp/utsout_2836_1_2.ado" 75083 lines, 5370280 characters /oracle/app/oracle/diag/rdbms/anbob/anbob1/incident/incdir_1159673/anbob1_pz99_14635_i1159673.trc ---------------------------------------------------------- LEVEL PAYLOAD ----- ------------------------------------------------------------------------------------------------------------------------------------------------ Dump file /oracle/app/oracle/diag/rdbms/anbob/anbob1/incident/incdir_1159673/anbob1_pz99_14635_i1159673.trc Oracle Database 11g Enterprise Edition Release 11.2.0.3.0 - 64bit Production With the Partitioning, Real Application Clusters, OLAP, Data Mining and Real Application Testing options ORACLE_HOME = /oracle/app/oracle/product/11.2.0.3/dbhome_1 System name: HP-UX Node name: qdtza1 Release: B.11.31 Version: U Machine: ia64 Instance name: anbob1 Redo thread mounted by this instance: 1 Oracle process number: 957 Unix process pid: 14635, image: oracle@qdtza1 (PZ99) *** 2019-03-25 06:08:01.800 *** SESSION ID:(8225.5665) 2019-03-25 06:08:01.800 *** CLIENT ID:() 2019-03-25 06:08:01.800 *** SERVICE NAME:(SYS$USERS) 2019-03-25 06:08:01.800 *** MODULE NAME:() 2019-03-25 06:08:01.800 *** ACTION NAME:() 2019-03-25 06:08:01.800 Dump continued from file: /oracle/app/oracle/diag/rdbms/anbob/anbob1/trace/anbob1_pz99_14635.trc 1> ***** Error Stack ***** ORA-00600: internal error code, arguments: [kxspoac : EXL 1], [2000], [32], [], [], [], [], [], [], [], [], [] 1< ***** Error Stack ***** 1> ***** Dump for incident 1159673 (ORA 600 [kxspoac : EXL 1]) ***** *** 2019-03-25 06:08:01.803 dbkedDefDump(): Starting incident default dumps (flags=0x2, level=3, mask=0x0) 2> ***** Current SQL Statement for this session (sql_id=6mvfay19q3v4n) ***** SELECT COUNT(CLIENT_INFO) FROM GV$SESSION WHERE USERNAME=:B2 AND CLIENT_INFO = :B1 GROUP BY CLIENT_INFO 2< ***** current_sql_statement ***** 2> ***** Call Stack Trace ***** 2< ***** call_stack_dump ***** skdstdst <- ksedst <- dbkedDefDump <- ksedmp <- ksfdmp <- $cold_dbgexPhaseII <- dbgexProcessError <- dbgeExecuteForError <- dbgePostErrorKGE <- dbkePostKGE_kgsf <- kgeadse <- kgerinv_internal <- kgerinv <- kgeasnmierr <- $cold_kxspoac <- opibnd0 <- opibnd <- kpoalbdf <- kpoal8 <- opiodr <- kpoodr <- upirtrc <- kpurcsc <- kpuexec <- OCIStmtExecute <- Error from uwx_step Stack is not Unwindab <- kxfxsStmtExecute <- kxfxsExecute <- kxfxsp <- kxfxmai <- ***** call_stack_dump <-
从MOS中不难查出Note #810194.1 与Bug 5045992 相关，但MOS中记录的是10.2.0.4 PSU后10503的行为忽略了number的变量的长度时会发生这个错误， 但看来我们sql中 GV$SESSION中username和client_info同为varchar也会出现该错误。
解决方法:
remove 10503 event and restart instance.
10503 EVENT
在之前的版本中为了修正Bug 2450264，提高sql 游标的共享性，引入了event 10503, EVENT 10503使用户能够指定字符绑定缓冲区长度, 然后使SQL cursor中使用相同的字符变量长度， 跳过字符变量不同刻度区间，可以使子游标chain相对较小， 有助力缓解sql cursor刻度共享问题， 因为默认字符绑定变量是分32, 128, 2000 和4000 bytes 4个刻度，当多列在不同的刻度区间时就原来有可能产生倍数级的sql cursor，做10046 SQL trace可以看到“mxl=32(实际长度)”的变量长度刻度, 比如一个SQL有 18 列变量，并且这些列中的每一列（原则上）都可以用 4 种不同的绑定分配大小之一声明，那么（原则上）可能有 power(4,18) – 大致 640 亿——需要不同的子游标来应对所提供数据的所有可能变化。EVENT 10503允许用户指定字符绑定缓冲区长度。根据使用的长度，子游标中的字符绑定都可以使用相同的绑定长度来创建，跳过绑定变更升级 减少SQL child chain，这有助于缓解与渐变绑定相关的潜在游标共享问题。 之前的案例中提到过SQL ordered by Version Count and Troubleshooting.
看一下案例
SQL> @sw "select sid from v$session where event like 'library%'"
SID STATE EVENT SEQ# SEC_IN_WAIT P1 P2 P3 P1TRANSL
------- ------- ---------------------------------------- ---------- ----------- ------------------- ------------------- ------------------- ------------------------------------------
8183 WAITING library cache: mutex X 480 106 idn= value= where= 19
0x000000003EB706D9 0x0000012800000000
8463 WAITING library cache: mutex X 334 154 idn= value= where= 85
0x000000003EB706D9 0x0000012800000000
3121 WAITING library cache: mutex X 289 154 idn= value= where= 85
0x000000003EB706D9 0x0000012800000000
SQL> select BLOCKING_INSTANCE,BLOCKING_SESSION_STATUS,BLOCKING_SESSION from v$session where sid=8183;
BLOCKING_INSTANCE BLOCKING_SE BLOCKING_SESSION
----------------- ----------- ----------------
2 VALID 296
SQL> @s 296
SID SQLID_AND_CHILD STATUS STATE EVENT SEQ# SEC_IN_WAIT BLOCKING_SID P1 P2 P3 P1TRANSL
------- -------------------- -------- ------- ---------------------------------------- ---------- ----------- ------------ ------------------ ------------------ ------------------ ------------------------------------------
296 4uqp4jczbf1qt ACTIVE WORKING On CPU / runqueue 331 171 NOT IN WAIT
SQL> select sql_fulltext from v$sqlarea where sql_id='&sqlid';
Enter value for sqlid: 4uqp4jczbf1qt
SQL_FULLTEXT
----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
insert into TXXXXX (
LOGINTICKET,
MARKETINGOID,
ISEMERGENCY,
BUSICHANCEORDERID,
PARENTID,
ORDERMODE,
ORDERID,
SUBRECDEFID,
MARKETID,
PICTUREID,
STATUSDATE,
STATUS,
NOTES,
DISCOUNT,
RECFEE,
DELEGATEID,
DELEGATEADDR,
CONTACTPHONE,
DELEGATEIDTYPE,
DELEGATENAME,
IPADDRESS,
MACADDR,
LINKREGION,
LINKTYPE,
RELATERECOID,
ISROLLBACK,
ISNOTIFY,
ISBACKPROCESS,
RECDATE,
RECOPID,
RECORGID,
OWNERORGID,
PRODID,
VERFITYTYPE,
RECDEFID,
ACCESSNUMBER,
SERVNUMBER,
CONTACTTYPE,
CUSTNAME,
CUSTID,
ENTITYID,
ENTITYTYPE,
FORMNUM,
GROUPID,
REGION,
OID,
CONTACTOP,
ISDELEGATEREC
)
values (
:V0,
:V1,
:V2,
:V3,
:V4,
:V5,
:V6,
:V7,
:V8,
:V9,
:V10,
:V11,
:V12,
:V13,
:V14,
:V15,
:V16,
:V17,
:V18,
:V19,
:V20,
:V21,
:V22,
:V23,
:V24,
:V25,
:V26,
:V27,
:V28,
:V29,
:V30,
:V31,
:V32,
:V33,
:V34,
:V35,
:V36,
:V37,
:V38,
:V39,
:V40,
:V41,
:V42,
:V43,
:V44,
:V45,
:V46,
:V47
);
SQL> select count(*) from v$sql where sql_id='4uqp4jczbf1qt';
COUNT(*)
----------
21372
SQL> select version_count from v$sqlarea where sql_id='4uqp4jczbf1qt';
VERSION_COUNT
-------------
74
SQL> @no_shared
Enter value for sqlid: 4uqp4jczbf1qt
SQL_ID NONSHARED_REASON COUNT(*)
------------- ----------------------------- ----------
4uqp4jczbf1qt BIND_MISMATCH 21428
4uqp4jczbf1qt HASH_MATCH_FAILED 290
4uqp4jczbf1qt BIND_LENGTH_UPGRADEABLE 17489
SQL> select /*+rule*/ m.position,m.bind_name , m.max_length,count(*) child_cursor_count
from v$sql s, v$sql_bind_metadata m
where s.sql_id = '4uqp4jczbf1qt'
and m.datatype=1
and s.child_address = m.address group by m.position,m.bind_name , m.max_length
order by 1, 2;
POSITION BIND_NAME MAX_LENGTH CHILD_CURSOR_COUNT
---------- ------------------------------ ---------- ------------------
1 V0 32 21668
2 V1 32 21668
3 V2 22 21668
4 V3 22 21668
5 V4 22 21668
6 V5 32 21668
7 V6 32 21668
8 V7 32 21668
9 V8 32 21668
10 V9 32 21668
11 V10 7 21668
12 V11 32 21668
13 V12 32 18251
13 V12 128 3105
13 V12 2000 312
14 V13 22 21668
15 V14 22 21668
16 V15 32 21668
17 V16 32 21456
17 V16 128 212
18 V17 32 21668
19 V18 32 21668
20 V19 32 21668
21 V20 32 21668
22 V21 32 21668
23 V22 22 21668
24 V23 32 21668
25 V24 22 21668
26 V25 22 21668
27 V26 22 21668
28 V27 22 21668
29 V28 7 21668
30 V29 32 21668
31 V30 32 21668
32 V31 32 21668
33 V32 32 21668
34 V33 32 21668
35 V34 32 21668
36 V35 32 21668
37 V36 32 21668
38 V37 32 21668
39 V38 32 19563
39 V38 128 2105
40 V39 22 21668
41 V40 22 21668
42 V41 32 21668
43 V42 32 21668
44 V43 22 21668
45 V44 22 21668
46 V45 22 21668
47 V46 32 21668
48 V47 22 21668
52 rows selected.
# enable 10503 level 2000 [max length]
SQL> alter system set events='10503 trace name context forever, level 2000';
System altered.
SQL> oradebug setmypid
Statement processed.
SQL> oradebug eventdump system
10503 trace name context forever, level 2000
10949 trace name context forever,level 1
28401 trace name context forever,level 1
SQL> alter system flush shared_pool;
System altered.
SQL> select count(*) from v$sql where sql_id='4uqp4jczbf1qt';
COUNT(*)
----------
0
SQL> select /*+rule*/ m.position,m.bind_name , m.max_length,count(*) child_cursor_count
2 from v$sql s, v$sql_bind_metadata m
3 where s.sql_id = '4uqp4jczbf1qt'
4 and m.datatype=1
5 and s.child_address = m.address group by m.position,m.bind_name , m.max_length
6 order by 1, 2;
POSITION BIND_NAME MAX_LENGTH CHILD_CURSOR_COUNT
---------- ------------------------------ ---------- ------------------
1 V0 2000 86
2 V1 2000 86
7 V6 2000 86
8 V7 2000 86
9 V8 2000 86
10 V9 2000 86
12 V11 2000 86
13 V12 2000 86
16 V15 2000 86
17 V16 2000 86
18 V17 2000 86
19 V18 2000 86
20 V19 2000 86
21 V20 2000 86
22 V21 2000 86
30 V29 2000 86
31 V30 2000 86
32 V31 2000 86
33 V32 2000 86
34 V33 2000 86
35 V34 2000 86
36 V35 2000 86
37 V36 2000 86
38 V37 2000 86
39 V38 2000 86
42 V41 2000 86
43 V42 2000 86
47 V46 2000 86
微信扫一扫，打赏作者吧～
对不起，这篇文章暂时关闭评论。