实战课堂:为什么更换存储之后一切正常但RAC集群启动不了?

这是一次来自生产实践的真实案例,某客户核心生产库由于进行新老存储替换变更操作后,Oracle RAC 两个节点均无法打开,数据库遭遇严重故障。

先来看看告警日志中记录的错误信息,我们注意到数据库能够正常Mount,但是在Open阶段遇到错误,提示某个数据文件不能被锁定:

ALTER DATABASE MOUNT This instance was first to mount Fri Dec 16 03:20:34 2016 Successful mount of redo thread 2, with mount id 3052566649 Fri Dec 16 03:20:40 2016 Database mounted in Shared Mode (CLUSTER_DATABASE=TRUE) Lost write protection disabled Completed: ALTER DATABASE MOUNT ALTER DATABASE OPEN This instance was first to open Fri Dec 16 03:00:53 2016 Errors in file /diag/ojtdb/ojtdb2/trace/ojtdb2_ora_1569.trc: ORA-01157: cannot identify/lock data file 1311 - see DBWR trace file ORA-01110: data file 1311: '/dev/vx/rdsk/ora_ojt10/ora_dev1311' ORA-1157 signalled during: ALTER DATABASE OPEN

通常遇到这个错误,最常见的原因是存储未正常挂载,或者数据文件损坏丢失。

通过dd检测发现I/O读正常,dbv检测数据文件也正常,这说明存储和数据文件的基本表现都属正常,而且不存在权限问题:

oracle$ time dd if=/dev/vx/rdsk/ora_ojt10/ora_dev1311 of=/dev/null bs=1024k count=1000 1000+0 records in 1000+0 records out real 0m1.654s user 0m0.006s sys 0m0.316s oracle$ dbv file=/dev/vx/rdsk/ora_ojt10/ora_dev1311 blocksize=8192

那么显然,这个问题跳出了传统的故障原因。

我们再回顾一下错误信息,数据库启动失败源自DBWR报错,可以通过进程跟踪来分析进程的工作状态。

在此我们通过v$session,分析DBW0进程当前的等待事件,排查dbwr进程迟迟不向其他进程发送相关ipc message的原因:

SQL> select event from v$session where paddr in (select addr from v$process where pid=<13>); EVENT ------------------------ Disk file operations I/O

DBWR 始终在执行磁盘 I/O 操作,Disk file operations I/O等待事件的官方解释如下:

This event is used to wait for disk file operations (for example, open, close, seek, and resize). It is also used for miscellaneous I/O operations such as block dumps and password file accesses. 此事件用于等待磁盘文件操作(例如,打开,关闭,搜索和调整大小)。 它也用于一些其他I / O操作,例如块转储和密码文件访问。

这个等待事件的三个参数p1,p2,p3 含义如下:

持续观察DBWR该事件的参数值,发现 p1=2,意思是 file open,在进行文件打开操作;p3=2,意思是操作数据文件。

而 p2 一直在递增变化,其含义是文件号,不断顺序的打开不同的数据文件。

说明DBW0正在逐个检查并打开数据文件,查询得知该库数据文件有1560个,在逐个检查进行到900秒后,后台alert日志中出现了如下错误,这一次出现问题的是另外一个文件:

ORA-01157: cannot identify/lock data file 1401 - see DBWR trace file ORA-01110: data file 1401: '/dev/vx/rdsk/ora_ojt10/ora_dev1401' ORA-1157 signalled during: ALTER DATABASE OPEN

在启动过程中,我们发现从mount到open阶段,报出 ORA-01157 和 ORA-01110 花费的时间很长,需要十几分钟,然后报错,使得启动过程强制终止;

最终是后台dbw进程在输出日志,为了进一步分析该过程中具体流程,于是开启10046事件跟踪dbw0进程:

*** 2016-12-16 12:03:30.798--这里时间是12点03,开始执行open操作 WAIT #0: nam='SQL*Net message from client' ela= 7344875 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=8068132685065 XCTEND rlbk=0, rd_only=1, tim=8068132685665 ===================== PARSING IN CURSOR #18446744071440810672 len=19 dep=0 uid=0 oct=35 lid=0 tim=8068132686043 hv=1907384048 ad='176ffabd68' sqlid='a01hp0psv0rrh' alter database open *** 2016-12-16 12:18:49.122 WAIT #18446744071440810672: nam='rdbms ipc reply' ela= 2010056 from_process=23 timeout=2 p3=0 obj#=-1 tim=8069051099141 *** 2016-12-16 12:18:51.038--之前都是空闲等待,从这个时间点开始,当前进程等待超时 ,发送超时消息给dbw0进程。而这个时间点18分。 WAIT #18446744071440810672: nam='ksdxexeotherwait' ela= 1915544 p1=0 p2=0 p3=0 obj#=-1 tim=8069053014980 WAIT #18446744071440810672: nam='control file sequential read' ela= 818 file#=0 block#=1 blocks=1 obj#=-1 tim=8069053016115 WAIT #18446744071440810672: nam='control file sequential read' ela= 496 file#=0 block#=39 blocks=1 obj#=-1 tim=8069053016665 WAIT #18446744071440810672: nam='control file sequential read' ela= 393 file#=0 block#=41 blocks=1 obj#=-1 tim=8069053017100 WAIT #18446744071440810672: nam='control file sequential read' ela= 8212 file#=0 block#=2300 blocks=1 obj#=-1 tim=8069053025356 WAIT #18446744071440810672: nam='CSS initialization' ela= 20622 p1=0 p2=0 p3=0 obj#=-1 tim=8069053046642 WAIT #18446744071440810672: nam='CSS operation: action' ela= 2656 function_id=65 p2=0 p3=0 obj#=-1 tim=8069053049357

从dbw0进程的跟踪日志来看,发现进程等待超时,然后发送超时消息给dbw0进程。从12:03分发起open操作,到12:18分出现超时消息,(18-3)*60 s = 900 s,即900秒后,后台发送超时消息给dbw0进程,而这个时间点正是后台报错而启动终止的时间。

这个信息给出了很好的分析线索,随即继续分析跟踪文件,详细分析每一次I/O的状态:

waited for 'Disk file operations I/O', seq_num: 617 p1: 'FileOperation'=0x2 p2: 'fileno'=0x1a9 p3: 'filetype'=0x2 time_waited: 0.696732 sec (sample interval: 0 sec) [1 sample, 07:57:37] waited for 'Disk file operations I/O', seq_num: 614 p1: 'FileOperation'=0x2 p2: 'fileno'=0x1a7 p3: 'filetype'=0x2 time_waited: 0.699569 sec (sample interval: 0 sec) [1 sample, 07:57:36] waited for 'Disk file operations I/O', seq_num: 613 p1: 'FileOperation'=0x2 p2: 'fileno'=0x1a6 p3: 'filetype'=0x2 time_waited: 0.682626 sec (sample interval: 0 sec) [1 sample, 07:57:35] waited for 'Disk file operations I/O', seq_num: 611 p1: 'FileOperation'=0x2 p2: 'fileno'=0x1a4 p3: 'filetype'=0x2 time_waited: 0.695486 sec (sample interval: 0 sec) [1 sample, 07:57:34] waited for 'Disk file operations I/O', seq_num: 610 p1: 'FileOperation'=0x2 p2: 'fileno'=0x1a3 p3: 'filetype'=0x2 time_waited: 0.700244 sec (sample interval: 0 sec) [1 sample, 07:57:33] waited for 'Disk file operations I/O', seq_num: 608 p1: 'FileOperation'=0x2 p2: 'fileno'=0x1a1 p3: 'filetype'=0x2 time_waited: 0.682131 sec (sample interval: 0 sec) --------------------------------------------------- Sampled Session History Summary: longest_non_idle_wait: 'Disk file operations I/O' [1 sample, 07:57:51 ] time_waited: 0.910736 sec (sample interval: 0 sec)

注意以上日志,可以发现平均打开一个数据文件的Disk file operations I/O操作大概需要0.7s左右,该库共有 1560个 数据文件,照此计算,打开所有数据文件大约需要1092秒,这个时间超出了之前得出的从发起open到报错终止的900秒的

那么我们接下来要想办法,让数据库在报错之前等待更久。

数据库中有一个隐藏参数 _controlfile_enqueue_timeout 默认为900s,该参数的意思是在数据库的 Open 阶段,锁定控制文件读取相关的数据文件并打开的允许超时时间,如果超过了900s阈值则认为数据库超时,会抛出异常,中断操作。

在此之前,我们估算了打开所有数据文件需要至少1092秒,这里在参数文件将该参数修改为9000s后,重新执行启动流程,最终成功打开了数据库的第二节点。

Fri Dec 16 12:52:22 2016 ALTER SYSTEM SET _controlfile_enqueue_timeout=9000 SCOPE=SPFILE; Fri Dec 16 12:52:22 2016 Shutting down instance (abort) License high water mark = 5 USER (ospid: 18936): terminating the instance Instance terminated by USER, pid = 18936 Fri Dec 16 12:52:30 2016 Instance shutdown complete Fri Dec 16 12:52:34 2016 Starting ORACLE instance (normal) Fri Dec 16 12:52:47 2016 … Fri Dec 16 12:56:39 2016 Database mounted in Shared Mode (CLUSTER_DATABASE=TRUE) Lost write protection disabled Completed: ALTER DATABASE MOUNT Fri Dec 16 12:57:19 2016 alter database open Fri Dec 16 13:15:42 2016 GTX0 started with pid=92, OS id=26326 replication_dependency_tracking turned off (no async multimaster replication found) Starting background process QMNC Fri Dec 16 13:15:43 2016 QMNC started with pid=93, OS id=26332 Completed: alter database open

从日志中,也清晰的看到,从12:57发起 alter database open 到最后完成open,耗时18分钟后,数据库成功open,数据库恢复正常。

这个案例给我们的警示是:

  • 在可能的情况下,任何变更都应该进行 1:1 真实测试,最大可能发现隐患;
  • 事关存储的变更,必须做好存储的读写I/O基准测试;

这个案例的后续是,分析新存储的I/O性能为何出现衰减,导致启动超时。这和存储的规划、磁盘划分、缓存配置等有关,数据库的案例到此就处理完成了。


近期文章

仅仅使用AWR做报告? 性能优化还未入门

实战课堂:一则CPU 100%的故障分析

杨廷琨:如何编写高效SQL(含PPT)

一份高达555页的技术PPT会是什么样子?

大象起舞:用PostgreSQL解海盗分金问题

原文发布于微信公众号 - 数据和云(OraNews)

原文发表时间:2018-06-13

本文参与腾讯云自媒体分享计划,欢迎正在阅读的你也加入,一起分享。

发表于

我来说两句

0 条评论
登录 后参与评论

相关文章

来自专栏杨建荣的学习笔记

Greenplum集群部署小记

Greenplum的分布式架构方案MPP对于海量数据处理还是很给力的,今天专门抽时间搭建了一下测试环境。

37520
来自专栏北京马哥教育

MySQL存储日志并使用Loganalyzer作为前端展示

为什么要使用日志 在生产环境中我们可能需要一个较为完整的日志系统来查看运行中主机服务的状态和所作出的操作,我们可以在较大型的网络架构中使用ELK来实现对日志的收...

34690
来自专栏专注研发

IDEA环境下SSM整合------环境配置

一、做不出详细的概念叙述和文本设计,本文主要以实战步骤为主,少量解释为辅助,下面请大家牢记两幅图:

17810
来自专栏禁心尽力

SpringBoot整合Mybatis之进门篇

已经有好些日子没有总结了,不是变懒了,而是我一直在奋力学习springboot的路上,现在也算是完成了第一阶段的学习,今天给各位总结总结。        之前...

1.7K60
来自专栏散尽浮华

分布式监控系统Zabbix3.4-针对MongoDB性能监控操作笔记

公司在IDC机房的一台服务器上部署了MongoDB,由于所存储的业务数据比较重要,所以对MongoDB的监控显得尤为重要!Zabbix监控MongoDB性能的原...

46840
来自专栏杨建荣的学习笔记

Data Guard高级玩法:通过闪回恢复switchover主库 (r10笔记第13天)

最近又试了下Data Guard的新玩法,可以通过闪回恢复switchover的主库,这种场景听起来比较特别,但是Oracle依旧支持。 我们的...

34770
来自专栏deed博客

交叉编译安卓busybox

20220
来自专栏王磊的博客

Spring Boot 最佳实践(五)Spring Data JPA 操作 MySQL 8

JPA(Java Persistence API)Java持久化API,是 Java 持久化的标准规范,Hibernate是持久化规范的技术实现,而Spring...

30820
来自专栏张戈的专栏

gh-ost:在线DDL修改MySQL表结构工具

在之前,我分享过一次 pt-online-schema-change 在线 DDL 的工具实践记录,在实际使用过程中,发现部门的很多老系统大量使用了触发器,从而...

1.1K70
来自专栏实战docker

pinpoint插件开发之一:牛刀小试,调整gson插件

从本章开始我们一起来实战pinpoint插件开发,做一些实用的pinpoint插件,本着先易后难的原则,我们从修改现有插件开始吧; 准备工作 本次实战的操作环境...

36950

扫码关注云+社区

领取腾讯云代金券