职业生涯最严重的一次宕机
昨天，经历了职业生涯中最令人心惊胆颤的危机，差点要去买锄头准备回家种地去了。-_-!!
早上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
……
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>
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>
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>
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顺序颠倒
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）。”
· 【文章发布信息】发表于： 2008-06-12 @ 00:46:46 · ||分类： ..experience, Working case
CopyRight ©
Jay 于 2008-06-12 @ 09:44:19 留言 ：
好险啊，连我都能感觉到。。~ 再加一万个小心。。
匿名 于 2008-06-12 @ 15:54:57 留言 ：
好紧张哦，体会到了备份高于一切的意思了。
卓尔不群 于 2008-06-12 @ 21:35:59 留言 ：
经历了4次心寒。。。。可想而知，当时是多大的打击。
死的心都有了。
当时那个悔啊。不可能的都在瞬间出现了。
。。。
只有经历过这样的事情，人才会成长，才能改变自己的思维以及想法。
niubro 于 2008-06-12 @ 22:36:21 留言 ：
备份永远是主要的。
人才都是这么锻炼出来的，这个时候才能体现出我们的价值：）
David.Guo 于 2008-06-13 @ 00:22:10 留言 ：
高手=辛苦的学习+血泪的教训
恭喜,你又想高手的目标迈进一步!
yxyup 于 2008-06-13 @ 11:45:58 留言 ：
发现vg_ora1上链路挂错了，重新配置后，数据库启动了
请问这是在哪步挂错了?
造成这个问题的最出原因是什么?
小荷 于 2008-06-13 @ 20:01:43 留言 ：
re yxyup：见HP的故障报告。
yxyup 于 2008-06-14 @ 12:28:57 留言 ：
造成这个问题的最出原因是什么?
小荷 于 2008-06-14 @ 13:22:32 留言 ：
re yxyup：和auto path的配置原理有关，里面的一些配置很容易引起自动挂载vg的时候有错误的配置。
jpork 于 2008-06-14 @ 15:52:43 留言 ：
确实惊险，不过好在有惊无险！
dbaeyes 于 2008-06-15 @ 23:34:34 留言 ：
老兄，确实很惊险！
备份高于一切，小心驶得万年船！
学习了！ 先努力向你靠近中 o(∩_∩)o…
paulyibinyi 于 2008-06-20 @ 09:07:47 留言 ：
惊险啊