由于TSM引起的数据库宕机

今天接到一个电话，一个应用的同事说的登录不上数据库，该数据库是在一台windows服务器上的，登录主机后，发现在系统的服务里面，oracle是启动的，但是登录数据库发现数据库已经宕机。检查数据库的alertlog发现：

Tue Oct 19 03:22:38 2010
Thread 1 advanced to log sequence 40786
  Current log# 3 seq# 40786 mem# 0: D:\ORACLE\ORADATA\JPJDE2\REDO03.LOG
Tue Oct 19 03:25:44 2010
Thread 1 advanced to log sequence 40787
  Current log# 1 seq# 40787 mem# 0: D:\ORACLE\ORADATA\JPJDE2\REDO01.LOG
Tue Oct 19 03:29:48 2010
Errors in file d:\oracle\admin\jpjde2\bdump\jpjde2_lgwr_2532.trc:
ORA-00321: log 2 of thread 1, cannot update log file header
ORA-00312: online log 2 thread 1: 'D:\ORACLE\ORADATA\JPJDE2\REDO02.LOG'
ORA-27091: skgfqio: unable to queue I/O
ORA-27041: unable to open file
OSD-04002: unable to open file
O/S-Error: (OS 32) The process cannot access the file because it is being used by another process.
 
Tue Oct 19 03:29:48 2010
Errors in file d:\oracle\admin\jpjde2\bdump\jpjde2_lgwr_2532.trc:
ORA-00321: log 2 of thread 1, cannot update log file header
 
LGWR: terminating instance due to error 321
Instance terminated by LGWR, pid = 2532

看来昨天晚上3点半左右，由于redo无法写入，（可能是被别的进程占据），因此实例被logwr进程给down掉了。

继续看trace文件：

Dump file d:\oracle\admin\jpjde2\bdump\jpjde2_lgwr_2532.trc
Tue Oct 19 03:29:47 2010
ORACLE V9.2.0.6.0 - Production vsnsta=0
vsnsql=12 vsnxtr=3
Windows 2000 Version 5.2 Service Pack 2, CPU type 586
Oracle9i Release 9.2.0.6.0 - Production
JServer Release 9.2.0.6.0 - Production
Windows 2000 Version 5.2 Service Pack 2, CPU type 586
Instance name: jpjde2
 
Redo thread mounted by this instance: 1
 
Oracle process number: 4
 
Windows thread id: 2532, image: ORACLE.EXE
 
 
*** 2010-10-19 03:29:47.984
*** SESSION ID:(3.1) 2010-10-19 03:29:47.921
ORA-00321: log 2 of thread 1, cannot update log file header
ORA-00312: online log 2 thread 1: 'D:\ORACLE\ORADATA\JPJDE2\REDO02.LOG'
ORA-27091: skgfqio: unable to queue I/O
ORA-27041: unable to open file
OSD-04002: unable to open file
O/S-Error: (OS 32) The process cannot access the file because it is being used by another process.
error 321 detected in background process
ORA-00321: log 2 of thread 1, cannot update log file header

在这个trace文件中，也没有更多的信息，说明是什么进程占据了redolog文件。怎么办？

这个时候，对系统维护“分块而治”的缺点就体现出来了，由于各个team只管自己的一块，没有整体的概念，根本不知道整个系统上部署了什么东西，是谁在起作用。

从头开始吧，先去问问wintel team，看看晚上有没有什么大的进程在跑，特别是可能会影响IO的东西，比如读取redo，或者晚上文件系统满，或者硬件故障，或者IO过于繁忙导致无法写redolog。但是wintel team的同事没有发现什么异常。但是我在问他的时候，发现他是去看控制面板里面的event log，这给了我一个思路：我可以去仔细check一下event log，这个和unix下的syslog类似，可以看到不少的系统信息。

果然，wintel team的同事看的比较粗，我在再次检查event log中application类型的时候，发现有不少报错：

而且，在对应的时间点，也就是down库前的关于redo的报错是在03:29:48：

那个时候，有个AdsmClientService资源在处理所有的oracle文件，也包含redo，而且，该进程还发现在处理redolog1过程中redolog1发生的变化，因此跳过该文件。
而我们的报错中是redolog2被别的进程说占据，根据log的sequence，我们看到该数据库是按照redolog3->redolog1->redolog2这样顺序切换。

因此，AdsmClientService进程的操作应该是在某一时刻，读取oracle目录下的一批文件，抓取后开始处理，如果文件在处理过程中文件发生变化，就skip该文件。从时间上看，当时应该是AdsmClientService进程同时抓取了redolog1，2，3，而且当时redolog1应该是current，所以AdsmClientService认为redolog1是有变化的，因此在报错信息中看到skip了该文件。但是redolog2和3应该是没有变化的，因此AdsmClientService进程是可以处理这2个文件的。

问题是，在AdsmClientService还在处理这一批文件的时候，发生了switch logfile，是oracle自己触发的，当需要从redolog1切换到redolog2的时候，redolog2在被AdsmClientService处理，所以就报错redolog被另一进程所占据，无法写redolog，lgwr进程使得instance终止。

其实这里存在一个侥幸：如果在处理redolog2的时候，没有发生switch logfile，数据库也就不会宕机。

那么，AdsmClientService进程究竟是做什么的？通过万能的Google发现，这个进程是和TSM有关的。

剩下的问题就比较好办了，找维护TSM的team确认，该进程是不是TSM的，当晚是不是有TSM对整个oracle目录的备份。

最终，TSM的维护的同学也确认了这个备份是新部署上去的，当晚确实有备份作业备份整个oracle目录下的所有文件。

通过在TSM中设置exclude oracle目录，就不再发生这个问题了。

取消了TSM的备份后，后续DBA要做的工作，就是设计oracle自己的备份计划了。

原文地址：http://www.oracleblog.org/working-case/database-down-by-tsm/