备案控制台
探索云世界
开发者社区 数据库 文章 正文

一次ORA-00600问题的排查和分析(下）

2015-06-12 898
版权
版权声明：
本文内容由阿里云实名注册用户自发贡献，版权归原作者所有，阿里云开发者社区不拥有其著作权，亦不承担相应法律责任。具体规则请查看《 阿里云开发者社区用户服务协议》和 《阿里云开发者社区知识产权保护指引》。如果您发现本社区中有涉嫌抄袭的内容，填写 侵权投诉表单进行举报，一经查实，本社区将立刻删除涉嫌侵权内容。
简介： 继续昨天对于 ORA-00600问题的排查和分析(上)http://blog.itpub.net/23718752/viewspace-1696076/我们发现了一大堆的ORA错误。
继续昨天对于 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中其实还有更多的明细信息。简单做了标注。
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的错误。
那么这个问题防范措施有哪些呢？
有几种思路来调整。但是最终都是调整隐含参数了。
第一种方案是调整下面两个隐含参数。
_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错误得到一些相关的信息。





文章标签：
机器翻译
日志服务
SQL
关系型数据库
监控
Perl
Oracle
jeanron100
目录
相关文章
小麦苗
|
Oracle 关系型数据库 Unix
Oracle中常用跟踪诊断trace配置
Oracle中常用跟踪诊断trace配置
小麦苗
199 0
郭一军_guoyJoe
|
缓存 Oracle 关系型数据库
重现ORA-01555错误
非常经典的一个一致性快照过旧的错误，Oracle面试必读。
郭一军_guoyJoe
530 0
文艺小青年
|
SQL Oracle Java
Oracle 常见错误排查
文艺小青年
1095 0
余二五
|
Oracle 关系型数据库 数据库
ora-01200错误的分析
余二五
1322 0
科技小能手
诊断ORA-08103错误
科技小能手
944 0
技术小胖子
|
SQL 运维 Oracle
【故障处理】ORA-12162 错误的处理
技术小胖子
1264 0
科技小能手
|
Windows
如何诊断ORA-125XX连接问题
科技小能手
1132 0
余二五
|
SQL 监控 Oracle
我的oracle 9i学习日志（7）—诊断文件与练习3
余二五
1144 0
苍雪明南
|
SQL 监控 Oracle
ORA-600(2662)错误的重现和解决（二）
前两天同事在测试DATA GUARD的时候将主库的ONLINE日志意外覆盖，造成数据库无法打开，采用隐含参数的方法打开又碰到ORA-600错误，最后采用设置EVENTS的方式解决。
苍雪明南
1281 0
苍雪明南
|
SQL 监控 Oracle
ORA-600(2662)错误的重现和解决（一）
前两天同事在测试DATA GUARD的时候将主库的ONLINE日志意外覆盖，造成数据库无法打开，采用隐含参数的方法打开又碰到ORA-600错误，最后采用设置EVENTS的方式解决。
苍雪明南
1252 0

热门文章

最新文章

  • 1
    理解事务的4种隔离级别
  • 2
    疑犯追踪第一季/全集Person Of Interest迅雷下载
  • 3
    简单实用的数据建模工具PDManer
  • 4
    详细讲解！Canal+Kafka实现MySQL与Redis数据同步！
  • 5
    71.7. Script for automatic startup on boot
  • 6
    关于Oracle客户端显示乱码问题
  • 7
    PHPWAMP站点管理的“域名模式”和“端口模式”详解、均支持自定义
  • 8
    jsHelper
  • 9
    学校里学不到的东西(一)
  • 10
    Python 3 教程一:入门
  • 1
    Python的装饰器
    30
  • 2
    R语言用潜类别混合效应模型(Latent Class Mixed Model ,LCMM)分析老年痴呆年龄数据
    20
  • 3
    数据分享|R语言用logistic逻辑回归和AFRIMA、ARIMA时间序列模型预测世界人口
    14
  • 4
    【视频】马尔可夫链蒙特卡罗方法MCMC原理与R语言实现|数据分享（下）
    18
  • 5
    【视频】马尔可夫链蒙特卡罗方法MCMC原理与R语言实现|数据分享（上）
    24
  • 6
    数据分享|数据探索电商平台用户行为流失可视化分析
    25
  • 7
    电商平台数据可视化分析网红零食销量
    17
  • 8
    R语言线性回归模型拟合诊断异常值分析家庭燃气消耗量和卡路里实例带自测题
    15
  • 9
    数据分享|R语言GLM广义线性模型：逻辑回归、泊松回归拟合小鼠临床试验数据（剂量和反应）示例和自测题
    12
  • 10
    数据分享|R语言逻辑回归、线性判别分析LDA、GAM、MARS、KNN、QDA、决策树、随机森林、SVM分类葡萄酒交叉验证ROC（下）
    15

    • 相关电子书

    更多
  • 基于日志trace的智能故障定位系统
  • Spark App自动化故障分析与诊断
  • 低代码开发师（初级）实战教程
    • 下一篇
    部署LAMP环境（Alibaba Cloud Linux 3）