ora-01115错误排错方法，系统表空间IO错误 数据损坏处理一则

同事最近遇到一个数据库问题，说是系统表空间出现坏块，警告日志文件中不断出现如下错误：

[oracle@gdmstest bdump]$ tail -20 alert_mydb.log
Linux Error: 4: Interrupted system call
Additional information: 23710
Wed Oct 25 16:47:44 2006
Errors in file /opt/oracle/admin/mydb/bdump/mydb_smon_19646.trc:
ORA-00604: error occurred at recursive SQL level 1
ORA-01115: IO error reading block from file 1 (block # 23712)
ORA-01110: data file 1: '/opt/oracle/oradata/mydb/system01.dbf'
ORA-27091: skgfqio: unable to queue I/O
ORA-27072: skgfdisp: I/O error
Linux Error: 4: Interrupted system call
Additional information: 23710
Wed Oct 25 16:47:59 2006
Errors in file /opt/oracle/admin/mydb/bdump/mydb_smon_19646.trc:
ORA-00604: error occurred at recursive SQL level 1
ORA-01115: IO error reading block from file 1 (block # 23712)
ORA-01110: data file 1: '/opt/oracle/oradata/mydb/system01.dbf'
ORA-27091: skgfqio: unable to queue I/O
ORA-27072: skgfdisp: I/O error
Linux Error: 4: Interrupted system call
Additional information: 23710

而通过dbv检查又没有报数据块损坏：

[oracle@gdmstest mydb]$ dbv file=system01.dbf blocksize=8192

DBVERIFY: Release 9.2.0.4.0 - Production on Thu Oct 26 11:36:42 2006

Copyright (c) 1982, 2002, Oracle Corporation. All rights reserved.

DBVERIFY - Verification starting : FILE = system01.dbf

DBVERIFY - Verification complete

Total Pages Examined : 23709
Total Pages Processed (Data) : 13000
Total Pages Failing (Data) : 0
Total Pages Processed (Index): 2090
Total Pages Failing (Index): 0
Total Pages Processed (Other): 1377
Total Pages Processed (Seg) : 0
Total Pages Failing (Seg) : 0
Total Pages Empty : 7242
Total Pages Marked Corrupt : 0
Total Pages Influx : 0

我们一起来看看这个问题，首先从错误日志来看，其实这并不是一个数据块损坏的问题：
ORA-01115: IO error reading block from file 1 (block # 23712)

这是个IO错误，数据块不能读取。

而DBV的提示也只是说检查了23709个数据块，这些数据块没有问题，而我们真正报错的数据块是23712号数据块，也就是说DBV检查到这个块附近，无法继续读取，进而退出。

而系统表空间远远大于 23709 * 8k / 1024 = 185M。

此时检查系统日志，dmesg日志中有大量的寻址错误，也就是说硬件出现了故障：

[maintain@gdmstest bdump]$ dmesg
: error=0x40 { UncorrectableError }, LBAsect=58847319, high=3, low=8515671, sector=14266880
end_request: I/O error, dev 03:06 (hda), sector 14266880
hda: dma_intr: status=0x51 { DriveReady SeekComplete Error }
hda: dma_intr: error=0x40 { UncorrectableError }, LBAsect=58847319, high=3, low=8515671, sector=14266880
end_request: I/O error, dev 03:06 (hda), sector 14266880
hda: dma_intr: status=0x51 { DriveReady SeekComplete Error }
hda: dma_intr: error=0x40 { UncorrectableError }, LBAsect=58847319, high=3, low=8515671, sector=14266880
end_request: I/O error, dev 03:06 (hda), sector 14266880
hda: dma_intr: status=0x51 { DriveReady SeekComplete Error }

至此问题被定位。

如果我们尝试cp系统表空间文件，同样会收到硬件的错误提示信息:

[oracle@gdmstest mydb]$ cp system01.dbf system01.dbf.bk
cp: 正在读入‘system01.dbf’: 输入/输出错误
[oracle@gdmstest mydb]$ ll
总用量 2173060
....
-rw-r----- 1 oracle dba 524296192 10月 25 16:49 system01.dbf
-rw-r----- 1 oracle dba 194236416 10月 25 17:00 system01.dbf.bk
...............

只能复制194236416 Bytes，也就是 194236416 / 8192 = 23710.5，同样是读到23709个数据块左右，硬件的损坏就要通过系统的其它手段去解决了。

方案2：

昨天，经历了职业生涯中最令人心惊胆颤的危机，差点要去买锄头准备回家种地去了。-_-!!

早上5点钟，被同事叫醒，说应用程序连数据库报TNS没响应。于是开始登录数据库主机。登录的时候，用常用的浮动IP连接，没响应，此时第一个反映就是是不是数据库主机挂了？难道要去机房？现在可是奥运前期，进出机房是件挺麻烦的事情……再试了试实际IP，幸好，登录进去了。check了一下进程和alertlog，发现是控制文件的读取有问题了：

Tue Jun 10 04:17:51 2008
Errors in file /oracle/app/oracle/admin/sd168/bdump/sd168_arc0_7605.trc:
ORA-00202: controlfile: '/dev/vg_ora1/rctrl_128m_01'
ORA-27091: skgfqio: unable to queue I/O
ORA-27072: skgfdisp: I/O error
HP-UX Error: 5: I/O error
Additional information: 1
Tue Jun 10 04:17:51 2008
KCF: write/open error block=0x44a online=1
Tue Jun 10 04:17:51 2008
Errors in file /oracle/app/oracle/admin/sd168/bdump/sd168_lgwr_7595.trc:
ORA-00345: redo log write error block 84121 count 2
ORA-00312: online log 2 thread 1: '/dev/vg_ora1/rredo_256m_02'
ORA-65535: Message 65535 not found;  product=RDBMS; facility=ORA
Tue Jun 10 04:17:51 2008
KCF: write/open error block=0xa251 online=1
     file=7 /dev/vg_ora1/rdata_1g_004
Tue Jun 10 04:17:51 2008
Errors in file /oracle/app/oracle/admin/sd168/udump/sd168_ora_16308.trc:
ORA-00202: controlfile: '/dev/vg_ora1/rctrl_128m_01'
ORA-27091: skgfqio: unable to queue I/O
ORA-27072: skgfdisp: I/O error
HP-UX Error: 5: I/O error
Additional information: 1
     file=1 /dev/vg_ora1/rsys_512m_01
     error=65535 txt: ''
Tue Jun 10 04:17:51 2008
Errors in file /oracle/app/oracle/admin/sd168/udump/sd168_ora_16562.trc:
ORA-00604: error occurred at recursive SQL level 1
ORA-01115: IO error reading block from file 1 (block # 820)
ORA-01110: data file 1: '/dev/vg_ora1/rsys_512m_01'
ORA-27091: skgfqio: unable to queue I/O
ORA-27072: skgfdisp: I/O error
HP-UX Error: 25: Not a typewriter
Additional information: 819
     error=65535 txt: ''
Tue Jun 10 04:17:51 2008
Errors in file /oracle/app/oracle/admin/sd168/bdump/sd168_ckpt_7597.trc:
ORA-00206: error in writing (block 3, # blocks 1) of controlfile
ORA-00202: controlfile: '/dev/vg_ora1/rctrl_128m_01'
ORA-65535: Message 65535 not found;  product=RDBMS; facility=ORA
Tue Jun 10 04:17:51 2008
……

赶紧请主机工程师也登录上来检查，主机工程师上来之后，重新把VG mount了一次，也重新在db01激活了一次（有做HP的MC双机热备），再次启动数据库，又是报错：

SQL> startup
ORA-27091: skgfqio: unable to queue I/O
ORA-27072: skgfdisp: I/O error
HP-UX Error: 6: No such device or address
Additional information: 720939
SQL>

坏了，vg_ora1上的spfile读不出来了，那换备份的pfile，用pfile到nomount，接着到mount时，再次报错：

SQL> startup nomount pfile='?/dbs/initsd168.ora.bak';
ORACLE instance started.
 
Total System Global Area 6453957408 bytes
Fixed Size                   746272 bytes
Variable Size            2147483648 bytes
Database Buffers         4294967296 bytes
Redo Buffers               10760192 bytesSQL> alter database mount;
alter database mount
*
ERROR at line 1:
ORA-00205: error in identifying controlfile, check alert log for more info
 
SQL>

查alertlog是控制文件1的问题，ok，在pfile中去掉控制文件1，再次mount，OK，没问题，再次open，报错找不到system的数据文件！！

SQL> startup nomount pfile='?/dbs/initsd168.ora.bak2';
ORACLE instance started.
 
Total System Global Area 6453957408 bytes
Fixed Size                   746272 bytes
Variable Size            2147483648 bytes
Database Buffers         4294967296 bytes
Redo Buffers               10760192 bytes
SQL>
SQL>
SQL> alter database mount;
 
Database altered.
SQL> alter database open;
alter database open
*
ERROR at line 1:
ORA-01122: database file 1 failed verification check
ORA-01110: data file 1: '/dev/vg_ora1/rsys_512m_01'
ORA-01251: Unknown File Header Version read for file number 1
 
SQL>

看来vg_ora1上的lv（裸设备）全完了！！

开始着手恢复措施：一方面，请主机工程师着手vg_ora1的恢复；另一方面，开始在db02上搭建环境，在上面做数据库的恢复。可是，一看备份，寒了，legato的数据库全备不知道被那个兄弟给disable了，最近的一次全备是今年的4月的！要追加2个月的arch，不知道要多久……-_-!!

进一步检查，备份的磁带还被recycle了。当时那个寒呀……

只好寄希望在主机那边的存储恢复了，终于，经过仔细的检查，发现vg_ora1上链路挂错了，重新配置后，数据库启动了……成功！此时已经中午12点半了。

通过这次事故，得到的教训还是很深刻的：

（1）备份高于一切，没有合适的备份，神仙都没办法救。必须保证备份的有效性和时效性。

（2）单点存储很危险，虽然有主机层面的MC双机热备，但是仅仅是存储挂在A机还是挂在B机的区别，要是存储坏了，后果很严重……就算有备份，恢复也是需要一段时间。如果有条件的话，还是做个DG比较安全……

（3）要有合适的还原策略，还原方案、还原脚本必须提前准备妥当，而不是待事故发生以后现场找数据库需要的LV，再划分VG和LV，再编写restore/recover脚本进行还原。

 

附：HP的诊断报告节选：

•故障过程
2008年6月10日凌晨4：10，PV c14t0d2从系统中消失
Jun 10 04:10:39 sd-db01 vmunix: AUTOPATH : Path 0xbc0a0200 failed! Rerouting toalternate path
Jun 10 04:10:39 sd-db01 vmunix: LVM: VG 64 0x010000: Lost quorum.
 
2008年6月10日凌晨4：17，PVc14t0d2复现，但是并非原先的Vdisk，从而产生“冲突”告警
Jun 10 04:17:48 sd-db01 vmunix: AUTOPATH : LUN collision occurred at:c16t0d2
Jun 10 04:17:48 sd-db01 vmunix: AUTOPATH : LUN collision occurred at:c10t0d2
Jun 10 04:17:48 sd-db01 vmunix: AUTOPATH : LUN collision occurred at:c14t0d2
Jun 10 04:17:48 sd-db01 vmunix: AUTOPATH : LUN collision occurred at:c12t0d2
 
2008年6月10日凌晨4：29, PV c14t0d6 产生“冲突”告警
Jun 10 04:29:41 sd-db01 vmunix: AUTOPATH : LUN collision occurred at:c14t0d6
 
2008年6月10日凌晨4：37，惠普响应中心接到贵方主机工程师报修，因为EVA中的Vdisk重新做过present，因而导致相应的vg_ora1不能激活，运行在该VG上的数据库无法启动。
 
起初受条件限制，惠普响应中心工程师无法直接远程登录系统，但了解到试图激活vg_ora1时，操作系统将有如下报错信息出现：
 
vgchange: Warning: couldn't query physical volume "/dev/dsk/c14t0d2":
The specified path does not correspond to physical volume attached to this volume group
vgchange: Warning: couldn't query physical volume "/dev/dsk/c16t0d2":
The specified path does not correspond to physical volume attached to this volume group
vgchange: Warning: couldn't query physical volume "/dev/dsk/c10t0d2":
The specified path does not correspond to physical volume attached to this volume group
vgchange: Warning: couldn't query physical volume "/dev/dsk/c12t0d2":
The specified path does not correspond to physical volume attached to this volume group
vgchange: Warning: couldn't query all of the physical volumes.
 
惠普工程师根据综合判断，指导用户用vgcfgrestore命令，将c14t0d2恢复到vg_ora1中。但由于此时的c14t0d2并非原来vg_ora1中所含PV，因而数据库无法启动。由于忽略了c14t0d2与c14t0d6两PV盘符颠倒，后面大部分时间是在做数据库诊断。
 
2008年 6月10日早上6：04，贵方主机工程师重新启动主机操作系统，问题依旧。
2008年6月10日早7：12，在使用vgimport命令对vg_ora1进行重建中，系统将盘头信息属于vg_ora1的所有PV同时归于旗下，因而会产生c14t0d2与c14t0d6同时属于该vg的现象。但是vg信息中记录该vg只包含一块PV，因而OS误将c14t0d6作为了c14t0d2的副路径（alternate link）。
Jun 10 07:12:36 sd-db01 LVM[5595]: vgexport -p -s -v -m newvg_ora1.map /dev/vg_ora1
Jun 10 07:13:12 sd-db01 LVM[5616]: vgexport /dev/vg_ora1
Jun 10 07:14:38 sd-db01 LVM[5704]: vgimport -s -v -m ./newvg_ora1.map /dev/vg_ora1
这为后面的进一步排查带来了更大的困难。
 
2008年6月10日中午12：17，在惠普远程后线专家反复分析检查后，终于发现问题所在，重建vg_ora1并在其后恢复应用。
 
Jun 10 12:17:02 sd-db01 LVM[14378]: vgexport -p -s -v -m vg_ora1.map /dev/vg_ora
1
Jun 10 12:19:20 sd-db01 LVM[14415]: vgchange -a n vg_ora1
Jun 10 12:19:40 sd-db01 LVM[14488]: vgexport vg_ora1
Jun 10 12:21:57 sd-db01 LVM[14521]: vgimport -m vg_ora1.map /dev/vg_ora1 /dev/ds
k/c10t0d6
Jun 10 12:22:37 sd-db01 su: + tg root-oracle
Jun 10 12:24:16 sd-db01 LVM[14586]: vgchange -c n vg_ora1
Jun 10 12:25:12 sd-db01 LVM[14675]: vgchange -a y vg_ora1
Jun 10 12:26:38 sd-db01 LVM[14700]: vgextend /dev/vg_ora1 /dev/dsk/c12t0d6 /dev/ dsk/c14t0d6 /dev/dsk/c16t0d6
Jun 10 12:26:38 sd-db01 LVM[14700]: Volume Group configuration for /dev/vg_ora1 has been saved in /etc/lvmconf/vg_ora1.conf
 
 
 
•故障分析
根据现场处理过程以及响应中心分析的结果，我们认为造成本次故障是如下原因：
1.对EVA上的Vdisk调整时将正在使用的Vdisk做了unpresent动作
2.重新present时将两个Vdisk顺序颠倒

PS:HP的auto path也不是个什么好东西：“在使用vgimport命令对vg_ora1进行重建中，系统将盘头信息属于vg_ora1的所有PV同时归于旗下，因而会产生c14t0d2与c14t0d6同时属于该vg的现象。但是vg信息中记录该vg只包含一块PV，因而OS误将c14t0d6作为了c14t0d2的副路径（alternate link）。”