NDMCDB数据库hang住故障分析-cursor:pinSwaitonX
问题描述： 上午刚刚到办公室，就有监控人员邮件反馈，昨晚NDMCDB407数据库被重启过，让我分析一下数据库重启的原因。由于昨晚业务有版本上线，所以短信警告关闭了，所以没有短信下发到我手机上，而且故障时相关人员也没有通知到我。 1 检查alert日志 从aler
问题描述：
上午刚刚到办公室，就有监控人员邮件反馈，昨晚NDMCDB407数据库被重启过，让我分析一下数据库重启的原因。由于昨晚业务有版本上线，所以短信警告关闭了，所以没有短信下发到我手机上，而且故障时相关人员也没有通知到我。
1 检查alert日志
从alert日志中，可以看到，先是在03:29时有一个job运行失败了：
Fri Aug 22 03:29:29 2014
Errors in file/opt/oracle/diag/rdbms/ndmcdb/NDMCDB/trace/NDMCDB_j000_28856.trc:
ORA-12012: error on auto execute of job 31
ORA-04023: ObjectNDMC.DELETE_ANONY_RSHARE_INFO could not be validated or authorized
ORA-06512: at "NDMC.PROC_NDMC_CANCEL_OPEN",line 5
ORA-06512: at line 1
然后在03:49时，出现了连接超时失败，而且一直持续到05:00:08：
Fri Aug 22 03:49:43 2014
***********************************************************************
Fatal NI connect error 12170.
VERSION INFORMATION:
TNS for Linux: Version 11.1.0.7.0 - Production
Oracle Bequeath NT Protocol Adapter for Linux: Version 11.1.0.7.0 -Production
TCP/IP NT Protocol Adapter for Linux: Version 11.1.0.7.0 - Production
Time: 22-AUG-2014 03:49:43
Tracing not turned on.
Tnserror struct:
ns main err code: 12535
TNS-12535: TNS:operation timed out
ns secondary err code: 12606
nt main err code: 0
nt secondary err code: 0
nt OS err code: 0
Client address: (ADDRESS=(PROTOCOL=tcp)(HOST=192.168.130.87)(PORT=36628))
WARNING: inbound connection timed out(ORA-3136)
Fri Aug 22 03:49:44 2014
……
而且出现了连接数耗尽了：
Fri Aug 22 03:49:50 2014
ORA-00020: maximum number of processes 0exceeded
ns secondary err code: 12560
ns secondary err code: 12560
ns main err code: 12537
Fri Aug 22 03:49:50 2014
……
Fri Aug 22 03:51:48 2014
***********************************************************************
Fatal NI connect error 12537, connectingto:
(LOCAL=NO)
VERSION INFORMATION:
TNS for Linux: Version 11.1.0.7.0 - Production
Oracle Bequeath NT Protocol Adapter for Linux: Version 11.1.0.7.0 -Production
TCP/IP NT Protocol Adapter for Linux: Version 11.1.0.7.0 - Production
Time: 22-AUG-2014 03:51:48
Tracing not turned on.
Tnserror struct:
ns main err code: 12537
TNS-12537: TNS:connection closed
ns secondaryerr code: 12560
nt main err code: 0
nt secondary err code: 0
nt OS err code: 0
ORA-609 : opiodr aborting process unknownospid (30476_47044991385184)
Fri Aug 22 04:14:15 2014
ORA-28 : opiodr aborting process unknownospid (24925_46986315964000)
Fri Aug 22 04:16:27 2014
ORA-28 : opiodr aborting process unknownospid (22475_47013891882592)
Fri Aug 22 04:16:28 2014
ORA-28 : opiodr aborting process unknownospid (21356_47116835528288)
Fri Aug 22 04:16:29 2014
ORA-28 : opiodr aborting process unknownospid (24947_47774766210656)
ORA-28 : opiodr aborting process unknownospid (14958_47053435166304)
……
Fri Aug 22 05:00:05 2014
ORA-28 : opiodr aborting process unknownospid (25765_46941307182688)
Fri Aug 22 05:00:08 2014
ORA-28 : opiodr aborting process unknownospid (4949_47396524895840)
于是在05:04数据库被关闭，从日志来看，这是正常关闭的，初步怀疑是人为关闭或是VCS双机自动将数据库关闭了：
Fri Aug 22 05:04:10 2014
Stopping background process SMCO
Stopping background process FBDA
Shutting down instance: further logonsdisabled
Fri Aug 22 05:04:12 2014
Stopping background process CJQ0
Stopping background process QMNC
Stopping background process MMNL
Stopping background process MMON
Shutting down instance (immediate)
License high water mark = 1220
Stopping Job queue slave processes, flags =7
Fri Aug 22 05:04:20 2014
Waiting for Job queue slaves to complete
Job queue slave processes stopped
Fri Aug 22 05:09:11 2014
License high water mark = 1220
USER (ospid: 25110): terminating theinstance
Termination issued to instance processes.Waiting for the processes to exit
Fri Aug 22 05:09:21 2014
Instance termination failed to kill one ormore processes
Instance terminated by USER, pid = 251102 检查messages日志
大概在05:03:51时，人为的想将双机切换到备机中：
Aug 22 05:03:51 NDMCDB11 user_cmd:2014-08-22 05:03:51 hagrp -switch RCS_DB_SG -to system by root from [oraclepts/9 Aug 22 04:29 (192.168.128.142)] Aug 22 05:04:01 NDMCDB11/usr/sbin/cron[15348]: (root) CMD (su - root -c'/opt/watchdog/watchdog_schedule -n OS,oracle' >/dev/null 2>&1) Aug 22 05:04:01 NDMCDB11 su: (to root) rooton none Aug 22 05:04:03 NDMCDB11 su: (to oracle)root on none Aug 22 05:04:09 NDMCDB11 user_cmd:2014-08-22 05:04:09 hagrp -switch RCS_DB_SG -to NDMCDB12 by root from [oraclepts/9 Aug 22 04:29 (192.168.128.142)] Aug 22 05:04:09 NDMCDB11 su: (to oracle)root on none
但双机切换失败，最后是直接将双机停止，重启VCS：
Aug 22 05:06:18 NDMCDB11 user_cmd:2014-08-22 05:06:18 hastop -all by root from [oracle pts/9 Aug 22 04:29(192.168.128.142)] …… Aug 22 05:07:02 NDMCDB11 user_cmd:2014-08-22 05:07:02 hastat by root from [oracle pts/9 Aug 22 04:29(192.168.128.142)]
所以，到这里就已经确定，数据库这所以重启了，完全是由于人为将VCS集群重启引起的。那么为什么要VCS群集重启呢？数据库到底有没有问题呢？再来看看。
最后，经向升级人员操作确认，在升级时，有一个存储过程需要跑，但执行后，数据库基本响应就非常慢了，一直运行到3:29左右，人为cancel掉了，所以这也就是为什么会出现这样的报错了：
Fri Aug 22 03:29:29 2014 Errors in file/opt/oracle/diag/rdbms/ndmcdb/NDMCDB/trace/NDMCDB_j000_28856.trc: ORA-12012: error on auto execute of job 31 ORA-04023: ObjectNDMC.DELETE_ANONY_RSHARE_INFO could not be validated or authorized ORA-06512: at"NDMC.PROC_NDMC_CANCEL_OPEN", line 5 ORA-06512: at line 1
3 查看系统负载
CPU负载：
内存负载：
可见，系统在3:49左右，出现了CPU及内存均被耗尽的情况，这个时间段，刚好数据库出现了大量连接超时失败，甚至是出现了连接数超过阀值：
Fri Aug 22 03:49:50 2014 ORA-00020: maximum number of processes 0exceeded ns secondary err code: 12560 ns secondary err code: 12560 ns main err code: 12537 Fri Aug 22 03:49:50 2014
4 分析AWR
从这里看，数据库在2点到3点时，已经非常的繁忙，但从之前有系统负载来看，2点到3点时，CPU及内存使用率都不算很高的。接着看：
指标都没有什么特别高的。
从top 5 event中，看到了有大量的cursor: pin S wait on X等待，可见出现mutex争用，但通常这只是表象而已，并非根因。
绝大部分时间都在做SQL的解析，而且解析还失败了，这就是数据库hang住的根因。正常来说，一个数据库的绝大部分时间应该是用于SQL的执行，所以这个是占用最多时间的：sql execute elapsedtime等。
不存在较高的versioncount。
那么数据库什么时候出现的不停解析SQL，并且解析失败了呢？
查了DBA_HIST_ACTIVE_SESS_HISTORY，分析了下历史会话信息，发现在02:57:00至03:00:00出现的问题：
经过确认，恰巧就是执行存储过程的时间点左右。
至此，数据库从3:00开始，已经是不正常的，数据库不停的在解析SQL，SQL都还没有到执行这一步，数据库已经处于无响应的状态，连接会话都被阻塞住了，直到连接数达到了最大连接数，最后被升级操作人员重启了VCS集群。
5 分析结论
（1）数据库down机主要还是人为进行了VCS切换失败后，进行了VCS重启操作引起。
（2）这套数据库故障的根因，还是为什么数据库在2:58左右时出现解析SQL失败上。从目前的日志分析来看，看不出是什么原因。
-- Bosco ---- END ----
热AI工具
Undresser.AI Undress
人工智能驱动的应用程序，用于创建逼真的裸体照片
AI Clothes Remover
用于从照片中去除衣服的在线人工智能工具。
Undress AI Tool
免费脱衣服图片
Clothoff.io
AI脱衣机
AI Hentai Generator
免费生成ai无尽的。
热门文章
热工具
记事本++7.3.1
好用且免费的代码编辑器
SublimeText3汉化版
中文版，非常好用
禅工作室 13.0.1
功能强大的PHP集成开发环境
Dreamweaver CS6
视觉化网页开发工具
SublimeText3 Mac版
神级代码编辑软件(SublimeText3)
热门话题
Go语言如何实现数据库的增删改查操作？
Mar 27, 2024 pm 09:39 PM
Go语言是一种高效、简洁且易于学习的编程语言，因其在并发编程和网络编程方面的优势而备受开发者青睐。在实际开发中，数据库操作是不可或缺的一部分，本文将介绍如何使用Go语言实现数据库的增删改查操作。在Go语言中，我们通常使用第三方库来操作数据库，比如常用的sql包、gorm等。这里以sql包为例介绍如何实现数据库的增删改查操作。假设我们使用的是MySQL数据库。
Hibernate 如何实现多态映射？
Apr 17, 2024 pm 12:09 PM
Hibernate多态映射可映射继承类到数据库，提供以下映射类型：joined-subclass：为子类创建单独表，包含父类所有列。table-per-class：为子类创建单独表，仅包含子类特有列。union-subclass：类似joined-subclass，但父类表联合所有子类列。
iOS 18 新增'已恢复”相册功能 可找回丢失或损坏的照片
Jul 18, 2024 am 05:48 AM
苹果公司最新发布的iOS18、iPadOS18以及macOSSequoia系统为Photos应用增添了一项重要功能，旨在帮助用户轻松恢复因各种原因丢失或损坏的照片和视频。这项新功能在Photos应用的"工具"部分引入了一个名为"已恢复"的相册，当用户设备中存在未纳入其照片库的图片或视频时，该相册将自动显示。"已恢复"相册的出现为因数据库损坏、相机应用未正确保存至照片库或第三方应用管理照片库时照片和视频丢失提供了解决方案。用户只需简单几步
深入解析HTML如何读取数据库
Apr 09, 2024 pm 12:36 PM
HTML无法直接读取数据库，但可以通过JavaScript和AJAX实现。其步骤包括建立数据库连接、发送查询、处理响应和更新页面。本文提供了利用JavaScript、AJAX和PHP来从MySQL数据库读取数据的实战示例，展示了如何在HTML页面中动态显示查询结果。该示例使用XMLHttpRequest建立数据库连接，发送查询并处理响应，从而将数据填充到页面元素中，实现了HTML读取数据库的功能。
如何在PHP中处理数据库连接错误
Jun 05, 2024 pm 02:16 PM
PHP中处理数据库连接报错，可以使用以下步骤：使用mysqli_connect_errno()获取错误代码。使用mysqli_connect_error()获取错误消息。通过捕获并记录这些错误信息，可以轻松识别并解决数据库连接问题，确保应用程序的顺畅运行。
在PHP中使用MySQLi建立数据库连接的详尽教程
Jun 04, 2024 pm 01:42 PM
如何在PHP中使用MySQLi建立数据库连接：包含MySQLi扩展（require_once）创建连接函数（functionconnect_to_db）调用连接函数（$conn=connect_to_db()）执行查询（$result=$conn->query()）关闭连接（$conn->close()）
PHP处理数据库中文乱码的技巧与实践
Mar 27, 2024 pm 05:21 PM
PHP是一种广泛应用于网站开发的后端编程语言，它具有强大的数据库操作功能，常用于与MySQL等数据库进行交互。然而，由于中文字符编码的复杂性，在处理数据库中文乱码时常常会出现问题。本文将介绍PHP处理数据库中文乱码的技巧与实践，包括常见的乱码原因、解决方法和具体的代码示例。常见的乱码原因数据库字符集设置不正确：数据库在创建时需选择正确的字符集，如utf8或u
如何在 Golang 中使用数据库回调函数？
Jun 03, 2024 pm 02:20 PM
在Golang中使用数据库回调函数可以实现：在指定数据库操作完成后执行自定义代码。通过单独的函数添加自定义行为，无需编写额外代码。回调函数可用于插入、更新、删除和查询操作。必须使用sql.Exec、sql.QueryRow或sql.Query函数才能使用回调函数。
