记录一次生产数据库的（性能）故障处理过程--（上）

最近碰到一个生产系统的（性能）故障处理过程。比较典型（其实不是典型，是比较搞笑），记录下来。

生产数据库架构：两个节点的RAC、单实例文件系统的Data guard 。应用上做了主备的读写分离，写操作在主库，读操作大部分在备库。

RDMBS： 12.2.0.1 （SGA 300G、PGA 100G，启用了大页面）

OS ： Oracle Linux 7 （具体是7的那个版本 ，没有留意 哈 ），CPU  144 Core，Momory  512G 。挺强悍的机器。

 

一 、主要问题：

1 客户提出主库在上午9点多的时候，出现了连接不到数据库的情况。然后客户进行了物理机的重启操作

2 客户提出，近期主库经常无响应（或者挂掉，客户说的挂是指无响应还是宕机后自动重启，没有说清楚），近期已经发现好几次。

3 客户告知，在前一天，rac集群的私网故障导致集群无法启动，当时说的是网卡坏了，但是有多余的网卡，告知客户在备份好网卡脚本的情况下，启用多余的网卡，并修改网卡ip和网卡名称。（客户有没有这样做，不清楚，只是后来集群和数据库启动起来了，后面因为数据库问题查看集群的时候，发现没有私网网卡坏的迹象）。（的确是坑，这个确实误导了后面解决问题）

二 、问题处理

接到这个问题的时候，物理机已经被客户重启。重启后有个小插曲。不知道怎么回事。rac主库的其中一个节点使用了pfile启动了。导致另一个节点无法启动。

主要原因嘛，使用了data guard。pfile和spfile里面的一些data guard参数居然不一致（的确是坑）。这个问题先放这里暂且不管。目前主备库都是同步的。主库还有一个节点可以进行分析。

这个问题，首先想到的是资源问题。因为没有部署oswatch等工具，没有办法确定当时的资源情况，只能分别打算从物理机的日志、集群日志、数据库日志、awr/ash中找一些蛛丝马迹。

1 分析了 主库两个节点的var log message 。好像没有什么有价值的信息 ，也看不到一些网卡损坏的信息。

2 分析集群的alert 日志。发现没有什么有价值的东西。没有发现因为资源问题导致集群节点被驱逐或者关闭。倒是发现日志中记录了被人为关闭的迹象（客户的确手工重启物理机了）

3 分析数据库日志。有些小发现。

网络方面的一些信息：

2021-04-06T11:28:27.412451+08:00
IPC Send timeout to 2.2 inc 12 for msg type 73 from opid 54
2021-04-06T11:28:27.412494+08:00
IPC Send timeout to 2.2 inc 12 for msg type 73 from opid 54
2021-04-06T11:28:27.412612+08:00
IPC Send timeout to 2.4 inc 12 for msg type 73 from opid 54
2021-04-06T11:28:27.412650+08:00
IPC Send timeout to 2.4 inc 12 for msg type 73 from opid 54
2021-04-06T11:28:27.412685+08:00
IPC Send timeout to 2.4 inc 12 for msg type 73 from opid 54
2021-04-06T11:28:27.412781+08:00
IPC Send timeout to 2.6 inc 12 for msg type 73 from opid 54
2021-04-06T11:28:27.412822+08:00
IPC Send timeout to 2.6 inc 12 for msg type 73 from opid 54
2021-04-06T11:28:27.413666+08:00
start recovery: pdb 0, passed in flags x10 (domain enable 0) 
2021-04-06T11:28:27.413714+08:00
Instance recovery: looking for dead threads
Instance recovery: lock domain invalid but no dead threads

另一个节点，好像没有什么特别的信息，还是因为dg配置问题，节点不能启动。这个先不考虑。

WARNING: The 'LOG_ARCHIVE_CONFIG' init.ora parameter settings
are inconsistent with another open instance.  This occurs
Starting background process ARC1
if the DG_CONFIG settings on this instance is different
then the DG_CONFIG settings on other open instances or if the
DB_UNIQUE_NAME parameter for this instance is set differently
than on other open instances.
2021-04-06T11:28:45.230955+08:00
Errors in file /oracle/ora_base/diag/rdbms/XXX/XXX2/trace/XXX2_lgwr_23732.trc:
ORA-16188: LOG_ARCHIVE_CONFIG settings inconsistent with previously started instance
2021-04-06T11:28:45.231229+08:00
Errors in file /oracle/ora_base/diag/rdbms/XXX/XXX2/trace/XXX2_ora_23838.trc:
ORA-16188: LOG_ARCHIVE_CONFIG settings inconsistent with previously started instance
2021-04-06T11:28:45.240336+08:00
ARC1 started with pid=101, OS id=23909 
2021-04-06T11:28:45.251026+08:00
USER (ospid: 23838): terminating the instance due to error 16188
2021-04-06T11:28:45.374964+08:00
System state dump requested by (instance=2, osid=23838), summary=[abnormal instance termination].
System State dumped to trace file /oracle/ora_base/diag/rdbms/XXX/XXX2/trace/XXX2_diag_23627_20210406112845.trc
2021-04-06T11:28:46.132796+08:00
Dumping diagnostic data in directory=[cdmp_20210406112845], requested by (instance=2, osid=23838), summary=[abnormal instance termination].
2021-04-06T11:28:47.281576+08:00
Instance terminated by USER, pid = 23838

在启动一个节点上，看到了一下信息，这个信息与MOS  Oracle Linux: ORA-27301:OS Failure Message: No Buffer Space Available (Doc ID 2041723.1)较类似 。这里比较坑啦，误导了。因为客户的网卡到底怎么回事，客户也没有说清楚，至于有没有更换网卡也没有说（后来看日志，感觉网卡没有更换。所以这里误导了以为网卡有问题）。

2021-04-05T18:54:09.514931+08:00
Errors in file /oracle/ora_base/diag/rdbms/XXX/XXX1/trace/XXX1_m000_219476.trc  (incident=1710820):
ORA-00603: ORACLE server session terminated by fatal error
ORA-27504: IPC error creating OSD context
ORA-27300: OS system dependent operation:sendmsg failed with status: 105
ORA-27301: OS failure message: No buffer space available
ORA-27302: failure occurred at: sskgxpsnd2

在alert log中又碰到了这些问题 ，继续误导中 

2021-04-06T09:38:39.061029+08:00
IPC Send timeout detected. Sender: ospid 235226 [oracle@XXXX (P075)]
Receiver: inst 2 binc 12 ospid 324262
2021-04-06T09:38:39.061299+08:00
IPC Send timeout detected. Sender: ospid 257387 [oracle@XXXX (P08F)]
Receiver: inst 2 binc 12 ospid 324262
2021-04-06T09:38:39.061762+08:00
IPC Send timeout detected. Sender: ospid 235211 [oracle@XXXX (P06T)]
Receiver: inst 2 binc 12 ospid 324262
2021-04-06T09:38:39.061836+08:00
IPC Send timeout detected. Sender: ospid 257572 [oracle@XXXX (P06C)]
Receiver: inst 2 binc 12 ospid 324262
2021-04-06T09:38:39.061946+08:00
IPC Send timeout detected. Sender: ospid 235007 [oracle@XXXX (P08J)]
Receiver: inst 2 binc 12 ospid 324262
2021-04-06T09:38:39.062032+08:00
IPC Send timeout detected. Sender: ospid 235293 [oracle@XXXX (P08E)]

alert log中，也碰到了一些dataguard的问题导致的hung。 继续误导中。

2021-04-06T09:18:46.619601+08:00
WARN: ARCH: Terminating process hung on an operation (PID:15116)

2021-04-06T09:18:58.337505+08:00
Killing 1 processes (PIDS:15116) (Process by index) in order to remove hung processes. Requested by OS process 15032 on instance 2
2021-04-06T09:18:58.956875+08:00

WARN: ARCH: Terminating process hung on an operation (PID:315297)
2021-04-06T09:39:12.164244+08:00
Killing 1 processes (PIDS:315297) (Process by index) in order to remove hung processes. Requested by OS process 15032 on instance 2
2021-04-06T09:39:14.167904+08:00
ARCH: krsv_hung_process_check: Error 16198 due to hung I/O operation to LOG_ARCHIVE_DEST_3
2021-04-06T09:39:44.181888+08:00
TT00: Gap Manager starting (PID:333310)
2021-04-06T09:40:44.255619+08:00

4 分析awr和ash （其实这里还有一个坑，客户一直说不准出现问题的时间和重启机器的时间。根据查看的数据库启动时间，感觉客户说的时间根本不对，坑啊）。只能抽取9点左右的awr。按照客户的说法一会儿9点故障一会儿11点故障。只能找个附近的报告，看下蛛丝马迹了。的确是坑。

从awr中，可以看到 concurrency类的等待事件排在第一位。（相比其他时间段的db time ，其他时间dbtime 大约30mins，这个时间点 dbtime 600多。快照间隔30min。这里就不贴那么多awr了。） 官方文档中描述在等待内部资源。 具体可以参考下官方文档：https://docs.oracle.com/cd/E11882_01/server.112/e40402/waitevents001.htm#BGGHJGII

 

在ASH中，可以看到一些会话的等待事件，是并行之类的等待事件。（这里没有保留报告，只是看了看）。

根据这些有限的信息。基本上判读如下：

针对数据库hung主的问题，
初步判断为当时数据库系统资源方面紧张，导致了数据库hung主。（后面发现的确是资源问题，具体问题，看下一篇的分析）
建议在网络方面、Data Guard传输归档、（这个的确是被误导了，受客户的更换网卡的信息误导，客户有没有更换网卡，模棱两可）
SQL语句方面进行调整优化。（这个占点边，后面一篇会分析）

 

分析到这里，基本上都得出的结论，是资源问题，各种原因引起的资源问题。需要进一步排查。

未完待续。

END