[Oracle]Redo log日志组故障分析(1)

ZDNet软件频道　时间：2008-09-22　作者：eygle | eygle　我要评论()
本文关键词：数据库 Oracle 日志组 redo log

数据库平台：SunOS 5.8 Generic_108528-23 sun4u sparc SUNW,Ultra-Enterprise 数据库版本：8.1.5.0.0 数据库症状：数据库响应缓慢，应用请求无法返回，业务操作陷于停顿，此时需要DBA介入并进行问题诊断及故障处理。

数据库平台：SunOS 5.8 Generic_108528-23 sun4u sparc SUNW,Ultra-Enterprise

　　数据库版本：8.1.5.0.0

　　数据库症状：数据库响应缓慢，应用请求无法返回，业务操作陷于停顿，此时需要DBA介入并进行问题诊断及故障处理。

　　1. 登录数据库进行检查

　　首先我们登录数据库,检查故障现象。
　　经过检查发现，数据块的所有重做日志组除current外都处于active状态：

Oracle:/Oracle/Oracle8>sqlplus "/ as sysdba"
SQL*Plus: Release 8.1.5.0.0 - Production on Thu Jun 23 18:56:06 2005
(c) Copyright 1999 Oracle Corporation.  All rights reserved.

Connected to:
Oracle8i Enterprise Edition Release 8.1.5.0.0 - Production
With the Partitioning and Java options
PL/SQL Release 8.1.5.0.0 - Production
SQL> select * from v$log;
    GROUP#    THREAD#  SEQUENCE#      BYTES    MEMBERS ARC STATUS           FIRST_CHANGE# FIRST_TIM
---------- ---------- ---------- ---------- ---------- --- ---------------- ------------- ---------
         1          1     520403   31457280          1 NO  ACTIVE              1.3861E+10 23-JUN-05
         2          1     520404   31457280          1 NO  ACTIVE              1.3861E+10 23-JUN-05
         3          1     520405   31457280          1 NO  ACTIVE              1.3861E+10 23-JUN-05
         4          1     520406   31457280          1 NO  CURRENT             1.3861E+10 23-JUN-05
         5          1     520398   31457280          1 NO  ACTIVE              1.3860E+10 23-JUN-05
         6          1     520399   31457280          1 NO  ACTIVE              1.3860E+10 23-JUN-05
         7          1     520400  104857600          1 NO  ACTIVE              1.3860E+10 23-JUN-05
         8          1     520401  104857600          1 NO  ACTIVE              1.3860E+10 23-JUN-05
         9          1     520402  104857600          1 NO  ACTIVE              1.3861E+10 23-JUN-05
9 rows selected.
SQL> /
    GROUP#    THREAD#  SEQUENCE#      BYTES    MEMBERS ARC STATUS           FIRST_CHANGE# FIRST_TIM
---------- ---------- ---------- ---------- ---------- --- ---------------- ------------- ---------
         1          1     520403   31457280          1 NO  ACTIVE              1.3861E+10 23-JUN-05
         2          1     520404   31457280          1 NO  ACTIVE              1.3861E+10 23-JUN-05
         3          1     520405   31457280          1 NO  ACTIVE              1.3861E+10 23-JUN-05
         4          1     520406   31457280          1 NO  CURRENT             1.3861E+10 23-JUN-05
         5          1     520398   31457280          1 NO  ACTIVE              1.3860E+10 23-JUN-05
         6          1     520399   31457280          1 NO  ACTIVE              1.3860E+10 23-JUN-05
         7          1     520400  104857600          1 NO  ACTIVE              1.3860E+10 23-JUN-05
         8          1     520401  104857600          1 NO  ACTIVE              1.3860E+10 23-JUN-05
         9          1     520402  104857600          1 NO  ACTIVE              1.3861E+10 23-JUN-05
9 rows selected.

　　我们知道，当数据库发生日志切换时（Log Switch）,Oracle会触发一个检查点（Checkpoint），检查点进程（Checkpoint Process，CKPT）会通知DBWR（Database?Writer）进程去执行写操作。在日志文件所保护的处于Buffer cache中的脏数据（dirty buffer）未写回磁盘之前，日志文件不能被覆盖或重用。
　　

　　如果数据库异常繁忙，或者DBWR的写出过慢，就可能出现检查点未完成，Oracle却已经用完所有日志文件的情况。在这种情况下，数据库的日志无法生成，整个数据库将处于停顿状态，此时日志文件中会记录类似如下信息：

Mon Jan 23 16:11:39 2006Thread 1 cannot allocate new log,
 sequence 5871Checkpoint not complete  Current log# 2 seq# 5870 mem# 0: 
+ORADG/danaly/onlinelog/group_2.260.600173851  
Current log# 2 seq# 5870 mem# 1: 
+ORADG/danaly/onlinelog/group_2.261.600173853

检查v$session_wait视图，我们可以从中看到很多session处于log file switch (checkpoint incomplete) 的等待。

　　2. 检查DBWR进程

　　在本案例中，所有日志组都处于active状态，那么显然DBWR的写出存在问题。

　　接下来让我们检查一下DBWR的繁忙程度:

SQL> !
Oracle:/Oracle/Oracle8>ps -ef|grep ora_
  Oracle  2273     1  0   Mar 31 ?       57:40 ora_smon_hysms02
  Oracle  2266     1  0   Mar 31 ?       811:42 ora_dbw0_hysms02
  Oracle  2264     1 16   Mar 31 ?       16999:57 ora_pmon_hysms02
  Oracle  2268     1  0   Mar 31 ?       1649:07 ora_lgwr_hysms02
  Oracle  2279     1  0   Mar 31 ?        8:09 ora_snp1_hysms02
  Oracle  2281     1  0   Mar 31 ?        4:22 ora_snp2_hysms02
  Oracle  2285     1  0   Mar 31 ?        9:40 ora_snp4_hysms02
  Oracle  2271     1  0   Mar 31 ?       15:57 ora_ckpt_hysms02
  Oracle  2283     1  0   Mar 31 ?        5:37 ora_snp3_hysms02
  Oracle  2277     1  0   Mar 31 ?        5:58 ora_snp0_hysms02
  Oracle  2289     1  0   Mar 31 ?        0:00 ora_d000_hysms02
  Oracle  2287     1  0   Mar 31 ?        0:00 ora_s000_hysms02
  Oracle  2275     1  0   Mar 31 ?        0:04 ora_reco_hysms02
  Oracle 21023 21012  0 18:52:59 pts/65   0:00 grep ora_