继续昨天对于 ORA-00600问题的排查和分析(上)
http://blog.itpub.net/23718752/viewspace-1696076/
我们发现了一大堆的ORA错误。我们首先排除了deadlock造成的ora-00600错误。从日志的分析的整体情况来说,虽然很多错误在metalink中都有相关的文章说明,但是提供的方案可执行性还是值得商榷的。毕竟一出现问题就是bug,就需要打补丁,就需要升级,这种处理方式客户也不会接受。在升级和打补丁之外,我们能够做些什么,能够避免这种问题也是解决问题。除此之外,我们所能做的就是进一步分析了,这时候分析除了深入分析日志中的内容,还需要结合数据库的整体情况来分析。
首先前2个ora错误都是数据库层面的问题,第3个错误可能看起来更严重。所以先来看看这个错误。
Archived Log entry 82993 added for thread 1 sequence 82927 ID 0xb8c6d509 dest 1:Wed Jun 10 14:38:53 2015
Errors in file /opt/app/oracle/dbccbspr1/diag/rdbms/PRODB/PRODB/trace/PRODB_ora_15548.trc (incident=2110436):
ORA-04030: out of process memory when trying to allocate 16328 bytes (koh-kghu sessi,pmucalm coll)
Incident details in: /opt/app/oracle/dbccbspr1/diag/rdbms/PRODB/PRODB/incident/incdir_2110436/PRODB_ora_15548_i2110436.trc
在trace中其实还有更多的明细信息。简单做了标注。
那么这个问题防范措施有哪些呢?
有几种思路来调整。但是最终都是调整隐含参数了。
第一种方案是调整下面两个隐含参数。
_use_realfree_heap=TRUE
_realfree_heap_pagesize_hint = 262144
根据项目的使用情况,建议的隐含参数调整如下,但是问题的处理不紧急,等问题解决之后可以后期进行跟进。
_kghdsidx_count 1
_optimizer_extended_cursor_sharing none
_optimizer_extended_cursor_sharing_rel none
所以这个ora的错误分析就告一段落,可以看出,这个错误主要是人为因素导致的,可以完全避免这种大批量的查询。在备库就可以达到同样的目的。
再来看看第一个和第二个错误。
第二个错误是ora-600错误,涉及的sql语句是核心层的sql语句,在其它项目都在使用,而且这个问题从错误日志的情况来看,之前还没有碰到过,所以尽管是一个bug,但是不是一个经常出现的问题。
ORA-00600: internal error code, arguments: [srsnext_3], [], [], [], [], [], [], [], [], [], [], []
我们来分析第一个问题,如果观察仔细,会发现和第三个错误还是有一些相关性的。都有parallel的相关错误。
Errors in file /opt/app/oracle/dbccbspr1/diag/rdbms/PRODB/PRODB/trace/PRODB_p135_15651.trc (incident=2116204):
ORA-07445: exception encountered: core dump [kxfpqrclb()+71] [SIGSEGV] [ADDR:0x210] [PC:0x193F4DF] [Address not mapped to object] []
ORA-10382: parallel query server interrupt (reset)
所以这个时候单纯在core dump的日志中从目前的情况来看还是很难分析出很多信息了。既然错误信息和parallel都有一些关联,我们来验证一下是不是确实由parallel导致了这些问题。
首先parallel的设置在这个环境是180,即最多能够启用180个并行。
再来看看错误信息就会发现。是在并行号为135的进程报出的错误。
Errors in file /opt/app/oracle/dbccbspr1/diag/rdbms/PRODB/PRODB/trace/PRODB_p135_15651.trc (incident=2116204):
在早晨的那个时间段,这个并行使用还是很高的。虽然时间已经过去了,但是还是能够通过ash发现不少信息的。
这个时候如果有额外的补充信息就会事半功倍了。
简单列出一些关键的信息。可以看出在那个时间段里,还是出现了很多的并行。我把session sid的信息给过滤了。
USERNAME OSUSER MACHINE PROGRAM DEGREE SERVER# REQ_DEGREE SQL_ID
--------------- --------------- -------------------- ------------------------------ -
APPC pwrk01 ccbdbpr oracle@ccbdbpr (P099) 8 3 8 a3hu6jraaw8t0
APPC pwrk01 ccbdbpr oracle@ccbdbpr (P100) 8 4 8 a3hu6jraaw8t0
APPC pwrk01 ccbdbpr oracle@ccbdbpr (P101) 8 5 8 a3hu6jraaw8t0
APPC pwrk01 ccbdbpr oracle@ccbdbpr (P102) 8 6 8 a3hu6jraaw8t0
APPC pwrk01 ccbdbpr oracle@ccbdbpr (P103) 8 7 8 a3hu6jraaw8t0
APPC pwrk01 ccbdbpr oracle@ccbdbpr (P104) 8 8 8 a3hu6jraaw8t0
APPC pwrk01 ccbdbpr oracle@ccbdbpr (P105) 8 1 8 5htvrhun1yqmr
APPC pwrk01 ccbdbpr oracle@ccbdbpr (P106) 8 2 8 5htvrhun1yqmr
APPC pwrk01 ccbdbpr oracle@ccbdbpr (P107) 8 3 8 5htvrhun1yqmr
APPC pwrk01 ccbdbpr oracle@ccbdbpr (P108) 8 4 8 5htvrhun1yqmr
APPC pwrk01 ccbdbpr oracle@ccbdbpr (P109) 8 5 8 5htvrhun1yqmr
APPC pwrk01 ccbdbpr oracle@ccbdbpr (P110) 8 6 8 5htvrhun1yqmr
APPC pwrk01 ccbdbpr oracle@ccbdbpr (P111) 8 7 8 5htvrhun1yqmr
APPC pwrk01 ccbdbpr oracle@ccbdbpr (P112) 8 8 8 5htvrhun1yqmr
APPC pwrk01 ccbdbpr oracle@ccbdbpr (P113) 8 8 8 g2k7z17gdtpdw
APPC pwrk01 ccbdbpr oracle@ccbdbpr (P115) 8 1 8 5htvrhun1yqmr
APPC pwrk01 ccbdbpr oracle@ccbdbpr (P116) 8 2 8 5htvrhun1yqmr
APPC pwrk01 ccbdbpr oracle@ccbdbpr (P117) 8 3 8 5htvrhun1yqmr
APPC pwrk01 ccbdbpr oracle@ccbdbpr (P118) 8 4 8 5htvrhun1yqmr
APPC pwrk01 ccbdbpr oracle@ccbdbpr (P119) 8 5 8 5htvrhun1yqmr
APPC pwrk01 ccbdbpr oracle@ccbdbpr (P120) 8 6 8 5htvrhun1yqmr
APPC pwrk01 ccbdbpr oracle@ccbdbpr (P153) 5 1 8 254xbkasy1ycy
APPC pwrk01 ccbdbpr oracle@ccbdbpr (P121) 8 7 8 5htvrhun1yqmr
APPC pwrk01 ccbdbpr oracle@ccbdbpr (P123) 8 8 8 5htvrhun1yqmr
APPC pwrk01 ccbdbpr oracle@ccbdbpr (P127) 4 2 8 gy93wucxgyzt3
APPC pwrk01 ccbdbpr oracle@ccbdbpr (P128) 4 3 8 gy93wucxgyzt3
APPC pwrk01 ccbdbpr oracle@ccbdbpr (P129) 4 4 8 gy93wucxgyzt3
APPC pwrk01 ccbdbpr oracle@ccbdbpr (P130) 2 1 8 a9jjv2z3kptdd
APPC pwrk01 ccbdbpr oracle@ccbdbpr (P163) 5 3 8 254xbkasy1ycy
APPC pwrk01 ccbdbpr oracle@ccbdbpr (P131) 2 2 8 a9jjv2z3kptdd
APPC pwrk01 ccbdbpr oracle@ccbdbpr (P132) 4 1 8 gy93wucxgyzt3
APPC pwrk01 ccbdbpr oracle@ccbdbpr (P133) 2 1 8 a9jjv2z3kptdd
APPC pwrk01 ccbdbpr oracle@ccbdbpr (P167) 5 4 8 254xbkasy1ycy
APPC pwrk01 ccbdbpr oracle@ccbdbpr (P134) 4 2 8 gy93wucxgyzt3
APPC pwrk01 ccbdbpr oracle@ccbdbpr (P135) 2 2 8 a9jjv2z3kptdd
我把相关的sql_id进行了整理,发现竟然sql语句都是类似的。比如下面两个sql语句。其实差别就在于标黄的部分,但是sql_id完全不同。
SQL_FULLTEXT
----------------------------------------------------------------------------------------------------
SELECT /*+ PARALLEL(8) */ MEMO.ENTITY_ID, MEMO.ENTITY_TYPE_ID, MEMO.ENTITY_TYPE_CODE, MEMO.MEMO_DATE
, ACT.ACT_PATH_ID FROM CSM_ACT_RSN ACT, (SELECT MM.ENTITY_ID, ET.ENTITY_TYPE_ID, ET.ENTITY_TYPE
_CODE, MM.MEMO_DATE, MT.MEMO_TYPE_ID FROM MO1_ENTITY_TYPE ET, MO1_MEMO_TYPE MT, MO1_MEMO MM
WHERE MM.ENTITY_TYPE_ID = ET.ENTITY_TYPE_ID AND MM.MEMO_TYPE_ID = MT.MEMO_TYPE_ID
AND MM.MEMO_ID BETWEEN :1 AND :2 AND MM.ENTITY_ID IN ( 8108188) AND ET.ENTITY_TYP
E_ID IN (2, 4, 6)) MEMO WHERE ACT.MEMO_TYPE=MEMO.MEMO_TYPE_ID AND ((MEMO.ENTITY_TYPE_ID = 2 AND AC
T.ACT_PATH_ID = 117) OR (MEMO.ENTITY_TYPE_ID = 4 AND ACT.ACT_PATH_ID = 126) OR (MEMO.E
NTITY_TYPE_ID = 6 AND ACT.ACT_PATH_ID IN (78, 84, 93))) GROUP BY MEMO.ENTITY_ID, MEMO.ENTITY_TYPE_I
D, MEMO.ENTITY_TYPE_CODE, MEMO.MEMO_DATE, ACT.ACT_PATH_ID
6cw70dcdtwu7p
SQL_FULLTEXT
----------------------------------------------------------------------------------------------------
SELECT /*+ PARALLEL(8) */ MEMO.ENTITY_ID, MEMO.ENTITY_TYPE_ID, MEMO.ENTITY_TYPE_CODE, MEMO.MEMO_DATE
, ACT.ACT_PATH_ID FROM CSM_ACT_RSN ACT, (SELECT MM.ENTITY_ID, ET.ENTITY_TYPE_ID, ET.ENTITY_TYPE
_CODE, MM.MEMO_DATE, MT.MEMO_TYPE_ID FROM MO1_ENTITY_TYPE ET, MO1_MEMO_TYPE MT, MO1_MEMO MM
WHERE MM.ENTITY_TYPE_ID = ET.ENTITY_TYPE_ID AND MM.MEMO_TYPE_ID = MT.MEMO_TYPE_ID
AND MM.MEMO_ID BETWEEN :1 AND :2 AND MM.ENTITY_ID IN ( 7341630) AND ET.ENTITY_TYP
E_ID IN (2, 4, 6)) MEMO WHERE ACT.MEMO_TYPE=MEMO.MEMO_TYPE_ID AND ((MEMO.ENTITY_TYPE_ID = 2 AND AC
T.ACT_PATH_ID = 117) OR (MEMO.ENTITY_TYPE_ID = 4 AND ACT.ACT_PATH_ID = 126) OR (MEMO.E
NTITY_TYPE_ID = 6 AND ACT.ACT_PATH_ID IN (78, 84, 93))) GROUP BY MEMO.ENTITY_ID, MEMO.ENTITY_TYPE_I
D, MEMO.ENTITY_TYPE_CODE, MEMO.MEMO_DATE, ACT.ACT_PATH_ID
通过这个我们可以分析出,还是存在绑定变量相关的潜在问题,这些类似的查询在做大量的并行,这个和预期是明显不同的。所以这个问题发送给开发同事去查看进行进一步确认。
可以看出大量的并行都是由某一个客户端发出的,和预期有很大的不同。
这是一个问题,另外一个问题就是有一些并行是通过开发人员制定的,这个就有些不合规范了。
怎么证明呢,我抓取了ora-00600发生的时间内的一个ash报告,是一个2分钟的报告。
在有限的几个查询中就看到了ora-00600发生的时候,有两个查询在做手工指定的并行,
通过这个问题我们可以看出,问题基本可以断定在并行的使用上,一个就是某个客户端在使用大量的并行查询,导致核心模块的sql在使用并行时出现ora-00600问题,同时有部分开发人员也在客户端进行一些并行查询,也是一个侧面的因素。
而关于客户端并行使用不当可以从第一个和第三个ora错误得到一些相关的信息。
http://blog.itpub.net/23718752/viewspace-1696076/
我们发现了一大堆的ORA错误。我们首先排除了deadlock造成的ora-00600错误。从日志的分析的整体情况来说,虽然很多错误在metalink中都有相关的文章说明,但是提供的方案可执行性还是值得商榷的。毕竟一出现问题就是bug,就需要打补丁,就需要升级,这种处理方式客户也不会接受。在升级和打补丁之外,我们能够做些什么,能够避免这种问题也是解决问题。除此之外,我们所能做的就是进一步分析了,这时候分析除了深入分析日志中的内容,还需要结合数据库的整体情况来分析。
首先前2个ora错误都是数据库层面的问题,第3个错误可能看起来更严重。所以先来看看这个错误。
Archived Log entry 82993 added for thread 1 sequence 82927 ID 0xb8c6d509 dest 1:Wed Jun 10 14:38:53 2015
Errors in file /opt/app/oracle/dbccbspr1/diag/rdbms/PRODB/PRODB/trace/PRODB_ora_15548.trc (incident=2110436):
ORA-04030: out of process memory when trying to allocate 16328 bytes (koh-kghu sessi,pmucalm coll)
Incident details in: /opt/app/oracle/dbccbspr1/diag/rdbms/PRODB/PRODB/incident/incdir_2110436/PRODB_ora_15548_i2110436.trc
在trace中其实还有更多的明细信息。简单做了标注。
less /opt/app/oracle/dbccbspr1/diag/rdbms/PRODB/PRODB/incident/incdir_2110436/PRODB_ora_15548_i2110436.trc
*** 2015-06-10 14:38:53.798
*** SESSION ID:(10891.46647) 2015-06-10 14:38:53.798
*** CLIENT ID:() 2015-06-10 14:38:53.798
*** SERVICE NAME:(SYS$USERS) 2015-06-10 14:38:53.798
*** MODULE NAME:(PL/SQL Developer) 2015-06-10 14:38:53.798
*** ACTION NAME:(SQL Window - Script_Find_Customer_XXXX_As_SOC_V2.sql) 2015-06-10 14:38:53.798
Dump continued from file: /opt/app/oracle/dbccbspr1/diag/rdbms/PRODB/PRODB/trace/PRODB_ora_15548.trc
ORA-04030: out of process memory when trying to allocate 16328 bytes (koh-kghu sessi,pmucalm coll)
========= Dump for incident 2110436 (ORA 4030) ========
----- Beginning of Customized Incident Dump(s) -----
=======================================
TOP 10 MEMORY USES FOR THIS PROCESS
---------------------------------------
91% 3719 MB, 238851 chunks: "pl/sql vc2 " PL/SQL
koh-kghu sessi ds=0x2ba75b6e1a48 dsprt=0x2ba75b6b40d0
9% 355 MB, 22799 chunks: "pmucalm coll " PL/SQL
koh-kghu sessi ds=0x2ba75b6e1a48 dsprt=0x2ba75b6b40d0
0% 1121 KB, 7 chunks: "free memory "
pga heap ds=0xb7f4bc0 dsprt=(nil)
0% 745 KB, 28 chunks: "permanent memory "
pga heap ds=0xb7f4bc0 dsprt=(nil)
0% 388 KB, 1 chunk : "free memory "
KSFD vec heap ds=0xb800980 dsprt=0xb7f4bc0
0% 125 KB, 2 chunks: "free memory "
top call heap ds=0xb7fa3e0 dsprt=(nil)
0% 63 KB, 1 chunk : "create partial row " SQL
kxs-heap-w ds=0x2ba75b6d4248 dsprt=0x2ba75b6b40d0
0% 58 KB, 36 chunks: "free memory "
session heap ds=0x2ba75b6b40d0 dsprt=0xb7fa600
0% 52 KB, 13 chunks: "kxsFrame4kPage "
session heap ds=0x2ba75b6b40d0 dsprt=0xb7fa600
0% 50 KB, 5 chunks: "permanent memory "
session heap ds=0x2ba75b6b40d0 dsprt=0xb7fa600
=======================================
PRIVATE MEMORY SUMMARY FOR THIS PROCESS
---------------------------------------
******************************************************
PRIVATE HEAP SUMMARY DUMP
4090 MB total:
4088 MB commented, 746 KB permanent
1247 KB free (0 KB in empty extents),
4087 MB, 1 heap: "session heap "
------------------------------------------------------
Summary of subheaps at depth 1
4085 MB total:
4085 MB commented, 69 KB permanent
457 KB free (0 KB in empty extents),
4084 MB, 9 heaps: "koh-kghu sessi " 21 KB free held
------------------------------------------------------
Summary of subheaps at depth 2
4074 MB total:
4074 MB commented, 32 KB permanent
8 KB free (0 KB in empty extents),
3719 MB, 238851 chunks: "pl/sql vc2 "
=========================================
REAL-FREE ALLOCATOR DUMP FOR THIS PROCESS
-----------------------------------------
......
2ba85b544000-2ba85b554000 rwxp 00000000 00:11 198613 /dev/zero
2ba85b554000-2ba85c9d4000 rwxp ffb79000 00:11 198613 /dev/zero
7fffbada1000-7fffbade1000 rwxp 7ffffffbe000 00:00 0 [stack]
7fffbadfd000-7fffbae00000 r-xp 7fffbadfd000 00:00 0 [vdso]
ffffffffff600000-ffffffffffe00000 ---p 00000000 00:00 0 [vsyscall]
******************* End of process map dump ************
其实上面的信息可以看到,对于进程都有4G的限制,从最后的日志可以看到,每个进程 仅仅有 65536 个 memory map 条目。
这个参数和操作系统层面是有关联的。
> cat /proc/sys/vm/max_map_count
65536
更重要的是发现是客户端的一个程序在运行sql脚本,而且是通过 PL/SQL Developer来运行的。
这个时候耐心看看日志其实还有一些明细信息。在trace日志的最后有下面一段内容,用黄色标注出来了。
Begin OCI Call Context Dump
End OCI Call Context Dump
Begin Process state dump.
ttcdrvdmplocation: msg-0 ln-0 reporting 0
hstflg: 0x40202d91
hstcflg: 0x00000000
hstpro: 6
hstccs: (DESCRIPTION=(ADDRESS=(PROTOCOL=TCP)(HOST=172.16.12.119)(PORT=1548))(CONNECT_DATA=(SID=PRODB)(CID=(PROGRAM=C:\Program Files\PLSQL Developer\plsqldev.exe)(HOST=XXXX_CP15-NICHAXXX)(USER=Nichaddsf))))
--- dump of hsttti ---
00B80AE10 00 01 01 0C 0E 09 0B 0F 01 0A 03 03 01 00 00 0A [................]
00B80AE20 00 00 00 00 00 00 00 01 01 01 01 01 01 01 01 01 [................]
00B80AE30 06 06 00 00 00 00 00 07 03 03 00 00 00 00 00 00 [................]
通过日志就可以看出这个问题是由于客户端通过plsql dev运行一个脚本导致进程占用超过4G的限制,所以抛出了ORA-04030的错误。*** 2015-06-10 14:38:53.798
*** SESSION ID:(10891.46647) 2015-06-10 14:38:53.798
*** CLIENT ID:() 2015-06-10 14:38:53.798
*** SERVICE NAME:(SYS$USERS) 2015-06-10 14:38:53.798
*** MODULE NAME:(PL/SQL Developer) 2015-06-10 14:38:53.798
*** ACTION NAME:(SQL Window - Script_Find_Customer_XXXX_As_SOC_V2.sql) 2015-06-10 14:38:53.798
Dump continued from file: /opt/app/oracle/dbccbspr1/diag/rdbms/PRODB/PRODB/trace/PRODB_ora_15548.trc
ORA-04030: out of process memory when trying to allocate 16328 bytes (koh-kghu sessi,pmucalm coll)
========= Dump for incident 2110436 (ORA 4030) ========
----- Beginning of Customized Incident Dump(s) -----
=======================================
TOP 10 MEMORY USES FOR THIS PROCESS
---------------------------------------
91% 3719 MB, 238851 chunks: "pl/sql vc2 " PL/SQL
koh-kghu sessi ds=0x2ba75b6e1a48 dsprt=0x2ba75b6b40d0
9% 355 MB, 22799 chunks: "pmucalm coll " PL/SQL
koh-kghu sessi ds=0x2ba75b6e1a48 dsprt=0x2ba75b6b40d0
0% 1121 KB, 7 chunks: "free memory "
pga heap ds=0xb7f4bc0 dsprt=(nil)
0% 745 KB, 28 chunks: "permanent memory "
pga heap ds=0xb7f4bc0 dsprt=(nil)
0% 388 KB, 1 chunk : "free memory "
KSFD vec heap ds=0xb800980 dsprt=0xb7f4bc0
0% 125 KB, 2 chunks: "free memory "
top call heap ds=0xb7fa3e0 dsprt=(nil)
0% 63 KB, 1 chunk : "create partial row " SQL
kxs-heap-w ds=0x2ba75b6d4248 dsprt=0x2ba75b6b40d0
0% 58 KB, 36 chunks: "free memory "
session heap ds=0x2ba75b6b40d0 dsprt=0xb7fa600
0% 52 KB, 13 chunks: "kxsFrame4kPage "
session heap ds=0x2ba75b6b40d0 dsprt=0xb7fa600
0% 50 KB, 5 chunks: "permanent memory "
session heap ds=0x2ba75b6b40d0 dsprt=0xb7fa600
=======================================
PRIVATE MEMORY SUMMARY FOR THIS PROCESS
---------------------------------------
******************************************************
PRIVATE HEAP SUMMARY DUMP
4090 MB total:
4088 MB commented, 746 KB permanent
1247 KB free (0 KB in empty extents),
4087 MB, 1 heap: "session heap "
------------------------------------------------------
Summary of subheaps at depth 1
4085 MB total:
4085 MB commented, 69 KB permanent
457 KB free (0 KB in empty extents),
4084 MB, 9 heaps: "koh-kghu sessi " 21 KB free held
------------------------------------------------------
Summary of subheaps at depth 2
4074 MB total:
4074 MB commented, 32 KB permanent
8 KB free (0 KB in empty extents),
3719 MB, 238851 chunks: "pl/sql vc2 "
=========================================
REAL-FREE ALLOCATOR DUMP FOR THIS PROCESS
-----------------------------------------
......
2ba85b544000-2ba85b554000 rwxp 00000000 00:11 198613 /dev/zero
2ba85b554000-2ba85c9d4000 rwxp ffb79000 00:11 198613 /dev/zero
7fffbada1000-7fffbade1000 rwxp 7ffffffbe000 00:00 0 [stack]
7fffbadfd000-7fffbae00000 r-xp 7fffbadfd000 00:00 0 [vdso]
ffffffffff600000-ffffffffffe00000 ---p 00000000 00:00 0 [vsyscall]
******************* End of process map dump ************
其实上面的信息可以看到,对于进程都有4G的限制,从最后的日志可以看到,每个进程 仅仅有 65536 个 memory map 条目。
这个参数和操作系统层面是有关联的。
> cat /proc/sys/vm/max_map_count
65536
更重要的是发现是客户端的一个程序在运行sql脚本,而且是通过 PL/SQL Developer来运行的。
这个时候耐心看看日志其实还有一些明细信息。在trace日志的最后有下面一段内容,用黄色标注出来了。
Begin OCI Call Context Dump
End OCI Call Context Dump
Begin Process state dump.
ttcdrvdmplocation: msg-0 ln-0 reporting 0
hstflg: 0x40202d91
hstcflg: 0x00000000
hstpro: 6
hstccs: (DESCRIPTION=(ADDRESS=(PROTOCOL=TCP)(HOST=172.16.12.119)(PORT=1548))(CONNECT_DATA=(SID=PRODB)(CID=(PROGRAM=C:\Program Files\PLSQL Developer\plsqldev.exe)(HOST=XXXX_CP15-NICHAXXX)(USER=Nichaddsf))))
--- dump of hsttti ---
00B80AE10 00 01 01 0C 0E 09 0B 0F 01 0A 03 03 01 00 00 0A [................]
00B80AE20 00 00 00 00 00 00 00 01 01 01 01 01 01 01 01 01 [................]
00B80AE30 06 06 00 00 00 00 00 07 03 03 00 00 00 00 00 00 [................]
那么这个问题防范措施有哪些呢?
有几种思路来调整。但是最终都是调整隐含参数了。
第一种方案是调整下面两个隐含参数。
_use_realfree_heap=TRUE
_realfree_heap_pagesize_hint = 262144
根据项目的使用情况,建议的隐含参数调整如下,但是问题的处理不紧急,等问题解决之后可以后期进行跟进。
_kghdsidx_count 1
_optimizer_extended_cursor_sharing none
_optimizer_extended_cursor_sharing_rel none
所以这个ora的错误分析就告一段落,可以看出,这个错误主要是人为因素导致的,可以完全避免这种大批量的查询。在备库就可以达到同样的目的。
再来看看第一个和第二个错误。
第二个错误是ora-600错误,涉及的sql语句是核心层的sql语句,在其它项目都在使用,而且这个问题从错误日志的情况来看,之前还没有碰到过,所以尽管是一个bug,但是不是一个经常出现的问题。
ORA-00600: internal error code, arguments: [srsnext_3], [], [], [], [], [], [], [], [], [], [], []
我们来分析第一个问题,如果观察仔细,会发现和第三个错误还是有一些相关性的。都有parallel的相关错误。
Errors in file /opt/app/oracle/dbccbspr1/diag/rdbms/PRODB/PRODB/trace/PRODB_p135_15651.trc (incident=2116204):
ORA-07445: exception encountered: core dump [kxfpqrclb()+71] [SIGSEGV] [ADDR:0x210] [PC:0x193F4DF] [Address not mapped to object] []
ORA-10382: parallel query server interrupt (reset)
所以这个时候单纯在core dump的日志中从目前的情况来看还是很难分析出很多信息了。既然错误信息和parallel都有一些关联,我们来验证一下是不是确实由parallel导致了这些问题。
首先parallel的设置在这个环境是180,即最多能够启用180个并行。
再来看看错误信息就会发现。是在并行号为135的进程报出的错误。
Errors in file /opt/app/oracle/dbccbspr1/diag/rdbms/PRODB/PRODB/trace/PRODB_p135_15651.trc (incident=2116204):
在早晨的那个时间段,这个并行使用还是很高的。虽然时间已经过去了,但是还是能够通过ash发现不少信息的。
这个时候如果有额外的补充信息就会事半功倍了。
简单列出一些关键的信息。可以看出在那个时间段里,还是出现了很多的并行。我把session sid的信息给过滤了。
USERNAME OSUSER MACHINE PROGRAM DEGREE SERVER# REQ_DEGREE SQL_ID
--------------- --------------- -------------------- ------------------------------ -
APPC pwrk01 ccbdbpr oracle@ccbdbpr (P099) 8 3 8 a3hu6jraaw8t0
APPC pwrk01 ccbdbpr oracle@ccbdbpr (P100) 8 4 8 a3hu6jraaw8t0
APPC pwrk01 ccbdbpr oracle@ccbdbpr (P101) 8 5 8 a3hu6jraaw8t0
APPC pwrk01 ccbdbpr oracle@ccbdbpr (P102) 8 6 8 a3hu6jraaw8t0
APPC pwrk01 ccbdbpr oracle@ccbdbpr (P103) 8 7 8 a3hu6jraaw8t0
APPC pwrk01 ccbdbpr oracle@ccbdbpr (P104) 8 8 8 a3hu6jraaw8t0
APPC pwrk01 ccbdbpr oracle@ccbdbpr (P105) 8 1 8 5htvrhun1yqmr
APPC pwrk01 ccbdbpr oracle@ccbdbpr (P106) 8 2 8 5htvrhun1yqmr
APPC pwrk01 ccbdbpr oracle@ccbdbpr (P107) 8 3 8 5htvrhun1yqmr
APPC pwrk01 ccbdbpr oracle@ccbdbpr (P108) 8 4 8 5htvrhun1yqmr
APPC pwrk01 ccbdbpr oracle@ccbdbpr (P109) 8 5 8 5htvrhun1yqmr
APPC pwrk01 ccbdbpr oracle@ccbdbpr (P110) 8 6 8 5htvrhun1yqmr
APPC pwrk01 ccbdbpr oracle@ccbdbpr (P111) 8 7 8 5htvrhun1yqmr
APPC pwrk01 ccbdbpr oracle@ccbdbpr (P112) 8 8 8 5htvrhun1yqmr
APPC pwrk01 ccbdbpr oracle@ccbdbpr (P113) 8 8 8 g2k7z17gdtpdw
APPC pwrk01 ccbdbpr oracle@ccbdbpr (P115) 8 1 8 5htvrhun1yqmr
APPC pwrk01 ccbdbpr oracle@ccbdbpr (P116) 8 2 8 5htvrhun1yqmr
APPC pwrk01 ccbdbpr oracle@ccbdbpr (P117) 8 3 8 5htvrhun1yqmr
APPC pwrk01 ccbdbpr oracle@ccbdbpr (P118) 8 4 8 5htvrhun1yqmr
APPC pwrk01 ccbdbpr oracle@ccbdbpr (P119) 8 5 8 5htvrhun1yqmr
APPC pwrk01 ccbdbpr oracle@ccbdbpr (P120) 8 6 8 5htvrhun1yqmr
APPC pwrk01 ccbdbpr oracle@ccbdbpr (P153) 5 1 8 254xbkasy1ycy
APPC pwrk01 ccbdbpr oracle@ccbdbpr (P121) 8 7 8 5htvrhun1yqmr
APPC pwrk01 ccbdbpr oracle@ccbdbpr (P123) 8 8 8 5htvrhun1yqmr
APPC pwrk01 ccbdbpr oracle@ccbdbpr (P127) 4 2 8 gy93wucxgyzt3
APPC pwrk01 ccbdbpr oracle@ccbdbpr (P128) 4 3 8 gy93wucxgyzt3
APPC pwrk01 ccbdbpr oracle@ccbdbpr (P129) 4 4 8 gy93wucxgyzt3
APPC pwrk01 ccbdbpr oracle@ccbdbpr (P130) 2 1 8 a9jjv2z3kptdd
APPC pwrk01 ccbdbpr oracle@ccbdbpr (P163) 5 3 8 254xbkasy1ycy
APPC pwrk01 ccbdbpr oracle@ccbdbpr (P131) 2 2 8 a9jjv2z3kptdd
APPC pwrk01 ccbdbpr oracle@ccbdbpr (P132) 4 1 8 gy93wucxgyzt3
APPC pwrk01 ccbdbpr oracle@ccbdbpr (P133) 2 1 8 a9jjv2z3kptdd
APPC pwrk01 ccbdbpr oracle@ccbdbpr (P167) 5 4 8 254xbkasy1ycy
APPC pwrk01 ccbdbpr oracle@ccbdbpr (P134) 4 2 8 gy93wucxgyzt3
APPC pwrk01 ccbdbpr oracle@ccbdbpr (P135) 2 2 8 a9jjv2z3kptdd
可以在那个时间段里,看到还是有很多的并行运行。而且奇怪的是很多并行都来自于pwrk01,这个和预期有很大的差距。
我把相关的sql_id进行了整理,发现竟然sql语句都是类似的。比如下面两个sql语句。其实差别就在于标黄的部分,但是sql_id完全不同。
SQL_FULLTEXT
----------------------------------------------------------------------------------------------------
SELECT /*+ PARALLEL(8) */ MEMO.ENTITY_ID, MEMO.ENTITY_TYPE_ID, MEMO.ENTITY_TYPE_CODE, MEMO.MEMO_DATE
, ACT.ACT_PATH_ID FROM CSM_ACT_RSN ACT, (SELECT MM.ENTITY_ID, ET.ENTITY_TYPE_ID, ET.ENTITY_TYPE
_CODE, MM.MEMO_DATE, MT.MEMO_TYPE_ID FROM MO1_ENTITY_TYPE ET, MO1_MEMO_TYPE MT, MO1_MEMO MM
WHERE MM.ENTITY_TYPE_ID = ET.ENTITY_TYPE_ID AND MM.MEMO_TYPE_ID = MT.MEMO_TYPE_ID
AND MM.MEMO_ID BETWEEN :1 AND :2 AND MM.ENTITY_ID IN ( 8108188) AND ET.ENTITY_TYP
E_ID IN (2, 4, 6)) MEMO WHERE ACT.MEMO_TYPE=MEMO.MEMO_TYPE_ID AND ((MEMO.ENTITY_TYPE_ID = 2 AND AC
T.ACT_PATH_ID = 117) OR (MEMO.ENTITY_TYPE_ID = 4 AND ACT.ACT_PATH_ID = 126) OR (MEMO.E
NTITY_TYPE_ID = 6 AND ACT.ACT_PATH_ID IN (78, 84, 93))) GROUP BY MEMO.ENTITY_ID, MEMO.ENTITY_TYPE_I
D, MEMO.ENTITY_TYPE_CODE, MEMO.MEMO_DATE, ACT.ACT_PATH_ID
6cw70dcdtwu7p
SQL_FULLTEXT
----------------------------------------------------------------------------------------------------
SELECT /*+ PARALLEL(8) */ MEMO.ENTITY_ID, MEMO.ENTITY_TYPE_ID, MEMO.ENTITY_TYPE_CODE, MEMO.MEMO_DATE
, ACT.ACT_PATH_ID FROM CSM_ACT_RSN ACT, (SELECT MM.ENTITY_ID, ET.ENTITY_TYPE_ID, ET.ENTITY_TYPE
_CODE, MM.MEMO_DATE, MT.MEMO_TYPE_ID FROM MO1_ENTITY_TYPE ET, MO1_MEMO_TYPE MT, MO1_MEMO MM
WHERE MM.ENTITY_TYPE_ID = ET.ENTITY_TYPE_ID AND MM.MEMO_TYPE_ID = MT.MEMO_TYPE_ID
AND MM.MEMO_ID BETWEEN :1 AND :2 AND MM.ENTITY_ID IN ( 7341630) AND ET.ENTITY_TYP
E_ID IN (2, 4, 6)) MEMO WHERE ACT.MEMO_TYPE=MEMO.MEMO_TYPE_ID AND ((MEMO.ENTITY_TYPE_ID = 2 AND AC
T.ACT_PATH_ID = 117) OR (MEMO.ENTITY_TYPE_ID = 4 AND ACT.ACT_PATH_ID = 126) OR (MEMO.E
NTITY_TYPE_ID = 6 AND ACT.ACT_PATH_ID IN (78, 84, 93))) GROUP BY MEMO.ENTITY_ID, MEMO.ENTITY_TYPE_I
D, MEMO.ENTITY_TYPE_CODE, MEMO.MEMO_DATE, ACT.ACT_PATH_ID
通过这个我们可以分析出,还是存在绑定变量相关的潜在问题,这些类似的查询在做大量的并行,这个和预期是明显不同的。所以这个问题发送给开发同事去查看进行进一步确认。
可以看出大量的并行都是由某一个客户端发出的,和预期有很大的不同。
这是一个问题,另外一个问题就是有一些并行是通过开发人员制定的,这个就有些不合规范了。
怎么证明呢,我抓取了ora-00600发生的时间内的一个ash报告,是一个2分钟的报告。
在有限的几个查询中就看到了ora-00600发生的时候,有两个查询在做手工指定的并行,
49jupn8xsj51y | 2518757642 | 1 | 5.65 | TABLE ACCESS - FULL | 5.41 | direct path read | 4.18 | select /*+ PARALLEL(b 8)*/ --c... |
7f2wq2wxvnxc5 | 1689491771 | 1 | 5.65 | TABLE ACCESS - FULL | 5.59 | direct path read | 3.88 | select /*+ PARALLEL(b 8)*/ b.s... |
通过这个问题我们可以看出,问题基本可以断定在并行的使用上,一个就是某个客户端在使用大量的并行查询,导致核心模块的sql在使用并行时出现ora-00600问题,同时有部分开发人员也在客户端进行一些并行查询,也是一个侧面的因素。
而关于客户端并行使用不当可以从第一个和第三个ora错误得到一些相关的信息。