一次ORA-00600问题的排查和分析(下)(r5笔记第65天)

继续昨天对于 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 2015Errors 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.trcORA-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 DUMP4090 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 14085 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 24074 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/zero2ba85b554000-2ba85c9d4000 rwxp ffb79000 00:11 198613 /dev/zero7fffbada1000-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_count65536更重要的是发现是客户端的一个程序在运行sql脚本，而且是通过PL/SQL Developer来运行的。Begin OCI Call Context DumpEnd OCI Call Context DumpBegin Process state dump.ttcdrvdmplocation: msg-0 ln-0 reporting 0hstflg: 0x40202d91hstcflg: 0x00000000hstpro: 6hstccs: (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的错误。再来看看第一个和第二个错误。第二个错误是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导致了这些问题。Errors in file /opt/app/oracle/dbccbspr1/diag/rdbms/PRODB/PRODB/trace/PRODB_p135_15651.trc (incident=2116204):USERNAME OSUSER MACHINE PROGRAM DEGREE SERVER# REQ_DEGREE SQL_IDP135) 2 2 8 a9jjv2z3kptdd

可以在那个时间段里，看到还是有很多的并行运行。而且奇怪的是很多并行都来自于pwrk01，这个和预期有很大的差距。

我把相关的sql_id进行了整理，发现竟然sql语句都是类似的。比如下面两个sql语句。其实差别就在于标黄的部分，但是sql_id完全不同。8108188) AND ET.ENTITY_TYP7341630) AND ET.ENTITY_TYP

通过这个问题我们可以看出，问题基本可以断定在并行的使用上，一个就是某个客户端在使用大量的并行查询，导致核心模块的sql在使用并行时出现ora-00600问题，同时有部分开发人员也在客户端进行一些并行查询，也是一个侧面的因素。