这是一次来自生产实践的真实案例, 某客户核心生产库由于进行新老存储替换变更操作后, 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 秒的.
那么我们接下来要想办法, 让数据库在报错之前等待更久.
怎么办呢? 让我们思考 1 秒钟...
数据库中有一个隐藏参数 _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 性能为何出现衰减, 导致启动超时. 这和存储的规划, 磁盘划分, 缓存配置等有关, 数据库的案例到此就处理完成了.
来源: http://stor.51cto.com/art/201806/577029.htm