ORA-03137: TTC protocol internal error : [12333] [7] [9] [50] [] [] [] []

--11G RAC 环境

Wed Jun 12 16:51:31 2019
LNS: Standby redo logfile selected for thread 1 sequence 523 for destination LOG_ARCHIVE_DEST_2
Wed Jun 12 16:51:32 2019
Archived Log entry 1465 added for thread 1 sequence 522 ID 0x9b8db1ed dest 1:
Wed Jun 12 16:58:51 2019
Errors in file /u01/app/oracle/diag/rdbms/ehdb/ehdb1/trace/ehdb1_ora_294593.trc (incident=522505):
ORA-03137: TTC protocol internal error : [12333] [7] [15] [56] [] [] [] []
Incident details in: /u01/app/oracle/diag/rdbms/ehdb/ehdb1/incident/incdir_522505/ehdb1_ora_294593_i522505.trc
Wed Jun 12 16:58:53 2019
Errors in file /u01/app/oracle/diag/rdbms/ehdb/ehdb1/trace/ehdb1_ora_295021.trc (incident=526801):
ORA-03137: TTC protocol internal error : [12333] [7] [8] [49] [] [] [] []
Incident details in: /u01/app/oracle/diag/rdbms/ehdb/ehdb1/incident/incdir_526801/ehdb1_ora_295021_i526801.trc
Wed Jun 12 16:58:53 2019
Errors in file /u01/app/oracle/diag/rdbms/ehdb/ehdb1/trace/ehdb1_ora_295188.trc (incident=531705):
ORA-03137: TTC protocol internal error : [12333] [7] [8] [49] [] [] [] []
Incident details in: /u01/app/oracle/diag/rdbms/ehdb/ehdb1/incident/incdir_531705/ehdb1_ora_295188_i531705.trc
Wed Jun 12 16:58:53 2019
Dumping diagnostic data in directory=[cdmp_20190612165853], requested by (instance=1, osid=294593), summary=[incident=522505].
Wed Jun 12 16:58:54 2019
Sweep [inc][531705]: completed
Sweep [inc][526801]: completed
Sweep [inc][522505]: completed
Sweep [inc2][522505]: completed
Wed Jun 12 16:58:54 2019
Errors in file /u01/app/oracle/diag/rdbms/ehdb/ehdb1/trace/ehdb1_ora_294784.trc (incident=524281):
ORA-03137: TTC protocol internal error : [12333] [7] [9] [50] [] [] [] []
Incident details in: /u01/app/oracle/diag/rdbms/ehdb/ehdb1/incident/incdir_524281/ehdb1_ora_294784_i524281.trc
Wed Jun 12 16:58:58 2019
Errors in file /u01/app/oracle/diag/rdbms/ehdb/ehdb1/trace/ehdb1_ora_294953.trc (incident=526081):
ORA-03137: TTC protocol internal error : [12333] [7] [2] [48] [] [] [] []
Incident details in: /u01/app/oracle/diag/rdbms/ehdb/ehdb1/incident/incdir_526081/ehdb1_ora_294953_i526081.trc
Wed Jun 12 16:58:58 2019
Errors in file /u01/app/oracle/diag/rdbms/ehdb/ehdb1/trace/ehdb1_ora_295140.trc (incident=531513):
ORA-03137: TTC protocol internal error : [12333] [7] [8] [49] [] [] [] []
Dumping diagnostic data in directory=[cdmp_20190612165900], requested by (instance=1, osid=294953), summary=[incident=526081].
Wed Jun 12 16:59:01 2019
Errors in file /u01/app/oracle/diag/rdbms/ehdb/ehdb1/trace/ehdb1_ora_296200.trc (incident=534505):
ORA-03137: TTC protocol internal error : [12333] [7] [8] [49] [] [] [] []
Wed Jun 12 16:59:06 2019
Errors in file /u01/app/oracle/diag/rdbms/ehdb/ehdb1/trace/ehdb1_ora_295877.trc (incident=534089):
ORA-03137: TTC protocol internal error : [12333] [7] [15] [56] [] [] [] []
Wed Jun 12 16:59:55 2019
Sweep [inc][534505]: completed
Sweep [inc][534089]: completed
Sweep [inc][531513]: completed
Sweep [inc][526081]: completed
Sweep [inc][524281]: completed
Sweep [inc2][531705]: completed
Sweep [inc2][526801]: completed
Sweep [inc2][526081]: completed
Sweep [inc2][524281]: completed

---trc 文件

*** 2019-06-12 16:58:51.307
dbkedDefDump(): Starting incident default dumps (flags=0x2, level=3, mask=0x0)
----- Current SQL Statement for this session (sql_id=88bju9dg9y09s) -----
SELECT QRS_SEQ.NEXTVAL FROM DUAL

09:50:58 SYS@ewdb1(ewdb1)> col name for a30
09:52:53 SYS@ewdb1(ewdb1)> col VALUE for a10
09:52:53 SYS@ewdb1(ewdb1)> col DESCRIB for a40
09:52:54 SYS@ewdb1(ewdb1)> set lines 200
09:52:54 SYS@ewdb1(ewdb1)> SELECT x.ksppinm NAME, y.ksppstvl VALUE, x.ksppdesc describ
09:52:55 2 FROM SYS.x$ksppi x, SYS.x$ksppcv y
09:52:55 3 WHERE x.inst_id = USERENV ('Instance')
09:52:56 4 AND y.inst_id = USERENV ('Instance')
09:52:56 5 AND x.indx = y.indx
09:52:57 6 AND x.ksppinm LIKE '%&par%';
Enter value for par: _optim_peek_user_binds
old 6: AND x.ksppinm LIKE '%&par%'
new 6: AND x.ksppinm LIKE '%_optim_peek_user_binds%'

NAME VALUE DESCRIB
------------------------------ ---------- ----------------------------------------
_optim_peek_user_binds TRUE enable peeking of user binds

Bug 9703463

根据MOS查看，和 Bug 9703463比较匹配，The 'Current SQL' Statement is using bind variables.时，会触发此BUG；

解决方案：禁用绑定变量窥探特性

1. The quickest solution is to apply the workaround of setting _optim_peek_user_binds to false to disable bind peeking. However, this may impact performance.
SQL> alter system set "_optim_peek_user_binds"=false;

关于ORA-03137 TTC问题,MOS上有专门故障排除工具，通过此工具上次对应的alert和trace日志后，可以自动生成解决方案，也可以直接提交SR；

ORA-3137 Troubleshooting Tool (文档 ID 1521913.1)

---修改后日志

Wed Jun 12 17:58:04 2019
ALTER SYSTEM SET _optim_peek_user_binds=FALSE SCOPE=SPFILE SID='*';

----查询隐含参数变量的值

col name for a30;
col value for a10;
select
x.ksppinm name,
y.ksppstvl value,
y.ksppstdf isdefault,
decode(bitand(y.ksppstvf,7),1,'MODIFIED',4,'SYSTEM_MOD','FALSE') ismod,
decode(bitand(y.ksppstvf,2),2,'TRUE','FALSE') isadj
from
sys.x$ksppi x,
sys.x$ksppcv y
where
x.inst_id = userenv('Instance') and
y.inst_id = userenv('Instance') and
x.indx = y.indx and
x.ksppinm='_optim_peek_user_binds'
order by
translate(x.ksppinm, ' _', ' ');

---查询结果

col name for a30
col VALUE for a10
col DESCRIB for a40
set lines 200
SELECT x.ksppinm NAME, y.ksppstvl VALUE, x.ksppdesc describ
FROM SYS.x$ksppi x, SYS.x$ksppcv y
WHERE x.inst_id = USERENV ('Instance')
AND y.inst_id = USERENV ('Instance')
AND x.indx = y.indx
AND x.ksppinm LIKE '%&par%';

10:01:34 SYS@ewdb1(ewdb1)> col name for a30
10:01:44 SYS@ewdb1(ewdb1)> col VALUE for a10
10:01:44 SYS@ewdb1(ewdb1)> col DESCRIB for a40
10:01:45 SYS@ewdb1(ewdb1)> set lines 200
10:01:45 SYS@ewdb1(ewdb1)> SELECT x.ksppinm NAME, y.ksppstvl VALUE, x.ksppdesc describ
10:01:46 2 FROM SYS.x$ksppi x, SYS.x$ksppcv y
10:01:46 3 WHERE x.inst_id = USERENV ('Instance')
10:01:47 4 AND y.inst_id = USERENV ('Instance')
10:01:47 5 AND x.indx = y.indx
10:01:48 6 AND x.ksppinm LIKE '%&par%';
Enter value for par: _optim_peek_user_binds
old 6: AND x.ksppinm LIKE '%&par%'
new 6: AND x.ksppinm LIKE '%_optim_peek_user_binds%'

NAME VALUE DESCRIB
------------------------------ ---------- ----------------------------------------
_optim_peek_user_binds FALSE enable peeking of user binds

----其他库

Tue Jun 18 21:17:39 2019
Errors in file /u01/app/oracle/diag/rdbms/ewdb/ewdb1/trace/ewdb1_ora_361541.trc (incident=681225):
ORA-03137: TTC protocol internal error : [12333] [32] [98] [97] [] [] [] []
Incident details in: /u01/app/oracle/diag/rdbms/ewdb/ewdb1/incident/incdir_681225/newmhzdb1_ora_361541_i681225.trc
Tue Jun 18 21:17:39 2019

---trc 文件

*** ACTION NAME:() 2019-06-18 21:17:39.345

Dump continued from file: /u01/app/oracle/diag/rdbms/ewdb/ewdb1/trace/ewdb1_ora_361541.trc
ORA-03137: TTC protocol internal error : [12333] [32] [98] [97] [] [] [] []

========= Dump for incident 681225 (ORA 3137 [12333]) ========

*** 2019-06-18 21:17:39.345
dbkedDefDump(): Starting incident default dumps (flags=0x2, level=3, mask=0x0)
----- Current SQL Statement for this session (sql_id=34ub0xwf3az6w) -----
update SS.T_QR_KA_BAT
SET ST_ID=:1 ,
UPDATE_TIME = sysdate
WHERE UUID=:2

---alter

Tue Jun 18 22:33:00 2019
Errors in file /u01/app/oracle/diag/rdbms/ewdb/ewdb1/trace/ewdb1_ora_48015.trc (incident=681097):
ORA-03137: TTC protocol internal error : [12333] [32] [52] [48] [] [] [] []
Incident details in: /u01/app/oracle/diag/rdbms/ewdb/ewdb1/incident/incdir_681097/ewdb1_ora_48015_i681097.trc
Tue Jun 18 22:33:01 2019

*** 2019-06-18 22:33:00.561
*** SESSION ID:(533.1523) 2019-06-18 22:33:00.561
*** CLIENT ID:() 2019-06-18 22:33:00.561
*** SERVICE NAME:(ewdb) 2019-06-18 22:33:00.561
*** MODULE NAME:(JDBC Thin Client) 2019-06-18 22:33:00.561
*** ACTION NAME:() 2019-06-18 22:33:00.561

--- PROTOCOL VIOLATION DETECTED ---
----- Dump Cursor sql_id=34ub0xwf3az6w xsc=0x7f209b168698 cur=0x7f209b141cf0 -----

LibraryHandle: Address=0x4d3a528208 Hash=1c357cdc LockMode=N PinMode=0 LoadLockMode=0 Status=VALD
ObjectName: Name=update SS.T_QR_KA_BAT
SET ST_ID=:1 ,
UPDATE_TIME = sysdate
WHERE UUID=:2

*** 2019-06-18 22:33:00.589
*** SESSION ID:(533.1523) 2019-06-18 22:33:00.589
*** CLIENT ID:() 2019-06-18 22:33:00.589
*** SERVICE NAME:(ewdb) 2019-06-18 22:33:00.589
*** MODULE NAME:(JDBC Thin Client) 2019-06-18 22:33:00.589
*** ACTION NAME:() 2019-06-18 22:33:00.589

Dump continued from file: /u01/app/oracle/diag/rdbms/ewdb/ewdb1/trace/ewdb1_ora_48015.trc
ORA-03137: TTC protocol internal error : [12333] [32] [52] [48] [] [] [] []

========= Dump for incident 681097 (ORA 3137 [12333]) ========

*** 2019-06-18 22:33:00.590
dbkedDefDump(): Starting incident default dumps (flags=0x2, level=3, mask=0x0)
----- Current SQL Statement for this session (sql_id=34ub0xwf3az6w) -----
update SS.T_QR_KA_BAT
SET ST_ID=:1 ,
UPDATE_TIME = sysdate
WHERE UUID=:2

---alter
Wed Jun 19 00:16:00 2019
Errors in file /u01/app/oracle/diag/rdbms/ewdb/ewdb1/trace/ewdb1_ora_258939.trc (incident=681153):
ORA-03137: TTC protocol internal error : [12333] [32] [102] [56] [] [] [] []
Incident details in: /u01/app/oracle/diag/rdbms/ewdb/ewdb1/incident/incdir_681153/ewdb1_ora_258939_i681153.trc
Wed Jun 19 00:16:01 2019

*** 2019-06-19 00:16:00.334
*** SESSION ID:(947.667) 2019-06-19 00:16:00.334
*** CLIENT ID:() 2019-06-19 00:16:00.334
*** SERVICE NAME:(ewdb) 2019-06-19 00:16:00.334
*** MODULE NAME:(JDBC Thin Client) 2019-06-19 00:16:00.334
*** ACTION NAME:() 2019-06-19 00:16:00.334

--- PROTOCOL VIOLATION DETECTED ---
----- Dump Cursor sql_id=gt2ahw7mhj731 xsc=0x7fa168fe29b8 cur=0x7fa168fd1cf0 -----

LibraryHandle: Address=0x4db6649ae8 Hash=e7089c61 LockMode=N PinMode=0 LoadLockMode=0 Status=VALD
ObjectName: Name=SELECT UUID,TRAN_DT,DEAL_NUM
FROM SS.T_QR_KA_BAT
WHERE UUID = :1
AND TRAN_DT = :2

----
*** 2019-06-19 00:16:00.443
dbkedDefDump(): Starting incident default dumps (flags=0x2, level=3, mask=0x0)
----- Current SQL Statement for this session (sql_id=gt2ahw7mhj731) -----
SELECT UUID,TRAN_DT,DEAL_NUM
FROM SS.T_QR_KA_BAT
WHERE UUID = :1
AND TRAN_DT = :2

*** 2019-06-19 01:17:09.848
*** SESSION ID:(7258.1907) 2019-06-19 01:17:09.848
*** CLIENT ID:() 2019-06-19 01:17:09.848
*** SERVICE NAME:(ewdb) 2019-06-19 01:17:09.848
*** MODULE NAME:(JDBC Thin Client) 2019-06-19 01:17:09.848
*** ACTION NAME:() 2019-06-19 01:17:09.848

--- PROTOCOL VIOLATION DETECTED ---
----- Dump Cursor sql_id=34ub0xwf3az6w xsc=0x7f43db708698 cur=0x7f43db6e1cf0 -----

alter system set "_optim_peek_user_binds"=false ;

col name for a30;
col value for a10;
select
x.ksppinm name,
y.ksppstvl value,
y.ksppstdf isdefault,
decode(bitand(y.ksppstvf,7),1,'MODIFIED',4,'SYSTEM_MOD','FALSE') ismod,
decode(bitand(y.ksppstvf,2),2,'TRUE','FALSE') isadj
from
sys.x$ksppi x,
sys.x$ksppcv y
where
x.inst_id = userenv('Instance') and
y.inst_id = userenv('Instance') and
x.indx = y.indx and
x.ksppinm='_optim_peek_user_binds'
order by
translate(x.ksppinm, ' _', ' ');