今天接到一个电话,一个应用的同事说的登录不上数据库,该数据库是在一台windows服务器上的,登录主机后,发现在系统的服务里面,oracle是启动的,但是登录数据库发现数据库已经宕机。检查数据库的alertlog发现:
1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 |
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文件:
1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 |
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自己的备份计划了。
2条评论
REDO有多大? TSM在备份REDO要很长时间吗?
TSM备份正好赶上switch logfile 太巧了…
是个测试库,redo不是很大,100M