[Oracle]Redo log日志组故障分析-railon-ChinaUnix博客

railon的ChinaUnix博客railon.blog.chinaunix.net

首页　| 　博文目录　| 　关于我

railon

博客访问： 1188878
博文数量： 253
博客积分： 5892
博客等级：大校
技术积分： 1942
用户组：普通用户
注册时间： 2011-02-24 14:20

文章分类

全部博文（253）

调试（1）
云计算（3）

Hadoop（3）
其他（5）
系统工具（12）

网络命令（1）

screen（3）

ssh（0）

tc（1）

ip（2）

iptables（2）

nmap（1）

netperf（1）

tcpdump（1）
应用软件（8）

编辑器（4）

浏览器（4）
网络应用（44）

消息队列（0）

Wiki（1）

Tomcat（4）

Apache（1）

Squid（2）

JBOSS（4）

日志（10）

版本控制（5）

文件同步（2）

文件服务器（12）

Nginx（3）
运维（56）

负载均衡（1）

架构（2）

压力测试（3）

高可用/高负载/可（2）

存储技术（7）

安全（17）

虚拟化（1）

性能调优（3）

运维监控（18）
操作系统（36）

Windows（1）

Linux（34）

freebsd（1）
编程（28）

php（3）

Perl（4）

Python（6）

shell（15）
国学（1）
硬件（2）
考试认证（7）
网络（2）

VPN（0）

以太网（1）

WLAN（1）

路由（0）
网络资源（2）
IT业界（1）
数据库（44）

其他（2）

BerkeleyDB（1）

Oracle（32）

MySQL（9）
未分配的博文（1）

文章存档

2012年（98）

2011年（155）

我的朋友

相关博文

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

分类： Oracle

2011-11-14 15:34:29

数据库平台：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

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> /

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_

　　DBWR的进程号是2266。
使用Top命令观察一下该进程的CPU耗用:

oracle:/oracle/oracle8>top

last pid: 21145; load averages: 3.38, 3.45, 3.67 18:53:38
725 processes: 711 sleeping, 1 running, 10 zombie, 3 on cpu
CPU states: 35.2% idle, 40.1% user, 9.4% kernel, 15.4% iowait, 0.0% swap
Memory: 3072M real, 286M free, 3120M swap in use, 1146M swap free

   PID USERNAME THR PRI NICE SIZE   RES STATE    TIME    CPU COMMAND
11855 smspf      1 59    0 1355M 1321M cpu/0   19:32 16.52% oracle
2264 oracle     1   0    0 1358M 1316M run    283.3H 16.36% oracle
11280 oracle     1 13    0 1356M 1321M sleep   79.8H 0.77% oracle
6957 smspf     15 29   10   63M   14M sleep 107.7H 0.76% java
17393 smspf      1 30    0 1356M 1322M cpu/1 833:05 0.58% oracle
29299 smspf      5 58    0 8688K 5088K sleep   18.5H 0.38% fee_ftp_get
21043 oracle     1 43    0 3264K 2056K cpu/9    0:01 0.31% top
20919 smspf     17 29   10   63M   17M sleep 247:02 0.29% java
25124 smspf      1 58    0   16M 4688K sleep    0:35 0.25% smif_status_rec
8086 smspf      5 23    0   21M   13M sleep   41.1H 0.24% fee_file_in
16009 root       1 35    0 4920K 3160K sleep    0:03 0.21% sshd2
25126 smspf      1 58    0 1355M 1321M sleep    0:26 0.20% oracle
2266 oracle     1 60    0 1357M 1317M sleep 811:42 0.18% oracle
11628 smspf      7 59    0 3440K 2088K sleep    0:39 0.16% sgip_client_ltz
26257 smspf     82 59    0 447M 178M sleep 533:04 0.15% java

　　我们注意到，2266号进程消耗的CPU不过0.18%,显然并不繁忙,DBWR并不繁忙，但是检查点无法完成，那么我们可以判断，瓶颈就很可能出现在IO上。

　　3. 检查IO状况

　　我们可以使用IOSTAT工具检查系统IO状况：

gqgai:/home/gqgai>iostat -xn 3
                    extended device statistics
    r/s    w/s   kr/s   kw/s wait actv wsvc_t asvc_t %w %b device
......
    0.0    0.0    0.0    0.0 0.0 0.0    0.0    0.0   0   0 c0t6d0
    1.8   38.4   32.4 281.0 0.0 0.7    0.0   16.4   0 29 c0t10d0
    1.8   38.4   32.4 281.0 0.0 0.5    0.0   13.5   0 27 c0t11d0
   24.8   61.3 1432.4 880.1 0.0 0.5    0.0    5.4   0 26 c1t1d0
    0.0    0.0    0.0    0.0 0.0 0.0    0.0    9.1   0   0 hurraysms02:vold(pid238)
                    extended device statistics
    r/s    w/s   kr/s   kw/s wait actv wsvc_t asvc_t %w %b device
........
    0.0    0.0    0.0    0.0 0.0 0.0    0.0    0.0   0   0 c0t6d0
    0.3    8.3    0.3   47.0 0.0 0.1    0.0    9.2   0   8 c0t10d0
    0.0    8.3    0.0   47.0 0.0 0.1    0.0    8.0   0   7 c0t11d0
   11.7   65.3 197.2 522.2 0.0 1.6    0.0   20.5   0 100 c1t1d0
    0.0    0.0    0.0    0.0 0.0 0.0    0.0    0.0   0   0 hurraysms02:vold(pid238)
                    extended device statistics
    r/s    w/s   kr/s   kw/s wait actv wsvc_t asvc_t %w %b device
........
    0.0    0.0    0.0    0.0 0.0 0.0    0.0    0.0   0   0 c0t6d0
    0.3   13.7    2.7   68.2 0.0 0.2    0.0   10.9   0 12 c0t10d0
    0.0   13.7    0.0   68.2 0.0 0.1    0.0    9.6   0 11 c0t11d0
   11.3   65.3   90.7 522.7 0.0 1.5    0.0   19.5   0 99 c1t1d0
    0.0    0.0    0.0    0.0 0.0 0.0    0.0    0.0   0   0 hurraysms02:vold(pid238)
                    extended device statistics
    r/s    w/s   kr/s   kw/s wait actv wsvc_t asvc_t %w %b device
........
    0.0    0.0    0.0    0.0 0.0 0.0    0.0    0.0   0   0 c0t6d0
    0.0    8.0    0.0   42.7 0.0 0.1    0.0    9.3   0   7 c0t10d0
    0.0    8.0    0.0   42.7 0.0 0.1    0.0    9.1   0   7 c0t11d0
   11.0   65.7 978.7 525.3 0.0 1.4    0.0   17.7   0 99 c1t1d0
    0.0    0.0    0.0    0.0 0.0 0.0    0.0    0.0   0   0 hurraysms02:vold(pid238)
                    extended device statistics
    r/s    w/s   kr/s   kw/s wait actv wsvc_t asvc_t %w %b device
........
    0.0    0.0    0.0    0.0 0.0 0.0    0.0    0.0   0   0 c0t6d0
    0.3   87.7    2.7 433.7 0.0 2.2    0.0   24.9   0 90 c0t10d0
    0.0   88.3    0.0 436.5 0.0 1.8    0.0   19.9   0 81 c0t11d0
   89.0   54.0 725.4 432.0 0.0 2.1    0.0   14.8   0 100 c1t1d0
    0.0    0.0    0.0    0.0 0.0 0.0    0.0    0.0   0   0 hurraysms02:vold(pid238)

　　在以上输出中，我们注意到，存放数据库的主要卷c1t1d0的繁忙程度始终处于99~100,而写速度却只有500K/s左右，这个速度是极为缓慢的。

　　根据IOSTAT的手册:

(%b percent of time the disk is busy (transactions in progress)
Kw/s kilobytes written per second)

　　根据我们的常识，T3盘阵通常按Char写速度可以达到10M/s左右，以前测试过一些Tpcc指标，可以参考：。

　　而正常情况下的数据库随机写通常都在1~2M左右，显然此时的磁盘已经处于不正常状态，经过确认的确是硬盘发生了损坏，Raid5的Group中损坏了一块硬盘。

　　经过更换以后系统逐渐恢复正常。

引文来源 [Oracle]Redo log日志组故障分析 - xuejinyoulan的专栏 - CSDNBlog

阅读(738) | 评论(0) | 转发(0) |

上一篇：Oracle进程导致CPU 100%具体解决步骤

下一篇：详细讲解Oracle物理结构故障的处理方法

给主人留下些什么吧！~~

感谢所有关心和支持过ChinaUnix的朋友们

16024965号-6