联机日志文件过小引发的log file 相关等待

  1. 云栖社区>
  2. 博客>
  3. 正文

联机日志文件过小引发的log file 相关等待

leshami 2013-03-25 11:51:14 浏览1044
展开阅读全文

      Oracle 联机重做日志文件记录了数据库的所有变化(DML,DDL或管理员对数据所作的结构性更改等),用于对于意外删除或宕机利用日志文件实现数据恢复来确保数据的完整性。但不合理的联机日志文件规划将引发日志相关的等待事件。下面是这样一个来自生产环境中的例子。

 

1、故障描述

--客户描述该数据库晚上用于实现数据同步以及汇总,以前一直工作的比较良好,随着需要同步的数量量的增大,最近变得越来越慢。
--下面我们首先取了客户晚8点至第二天7点的awr report。

WORKLOAD REPOSITORY report for

DB Name         DB Id    Instance     Inst Num Release     RAC Host
------------ ----------- ------------ -------- ----------- --- ------------
ST990         2152526631 ST990               1 10.2.0.3.0  NO  v2011db02p

              Snap Id      Snap Time      Sessions Curs/Sess
            --------- ------------------- -------- ---------
Begin Snap:     21787 21-Feb-13 20:00:22        50      19.5
  End Snap:     21798 22-Feb-13 07:00:47        44      20.0
   Elapsed:              660.42 (mins)
   DB Time:              928.06 (mins)

--从上面的awr report 可知,单实例,10.2.0.3版本,期间的会话数也不多
--Elapsed < DB Time
--Elapsed Time=(20130222 07:00:00 - 20130221 20:00:00)≈ 660
--DB Time=928.06 ,运行环境为16核CPU, 660*16=10560, cpu花费了928.06分钟在处理Oralce非空闲等待和运算上
--从上可知,整个系统还是比较空闲

--下面来看看top event
Top 5 Timed Events                                         Avg %Total
~~~~~~~~~~~~~~~~~~                                        wait   Call
Event                                 Waits    Time (s)   (ms)   Time Wait Class
------------------------------ ------------ ----------- ------ ------ ----------
CPU time                                         20,673          37.1
log file parallel write              27,399       4,797    175    8.6 System I/O
control file parallel write          13,428       4,688    349    8.4 System I/O
log file sync                        19,564       3,795    194    6.8     Commit
db file scattered read           26,651,537       3,439      0    6.2   User I/O

--从上面的top event事件上来看,log file相关等待事件表现明显
--log file parallel write等待事件总等待次数27,399 总等待时间4,797/60=79.95(min),超出一个小时,相当可观
--其次是control file parallel write与log file sync事件的相关等待

--下面是等待事件的detail信息
Wait Events                          DB/Inst: ST1200/ST1200  Snaps: 21787-21798
-> s  - second
-> cs - centisecond -     100th of a second
-> ms - millisecond -    1000th of a second
-> us - microsecond - 1000000th of a second
-> ordered by wait time desc, waits desc (idle events last)

                                             %Time  Total Wait    wait     Waits
Event                                 Waits  -outs    Time (s)    (ms)      /txn
---------------------------- -------------- ------ ----------- ------- ---------
log file parallel write              27,399     .0       4,797     175       1.1
control file parallel write          13,428     .0       4,688     349       0.5
log file sync                        19,564   10.6       3,795     194       0.8
db file scattered read           26,651,537     .0       3,439       0   1,049.4
db file sequential read           6,682,373     .0       1,567       0     263.1
log file switch (checkpoint           1,091   92.9       1,019     934       0.0
Datapump dump file I/O              633,458     .0         286       0      24.9
log file switch completion              332   31.6         183     552       0.0
log buffer space                        255   47.8         155     608       0.0
free buffer waits                     2,409   99.5         120      50       0.1
buffer busy waits                       145   62.8          96     664       0.0

2、分析故障

--客户描述该数据库晚上用于实现数据同步以及汇总,以前一直工作的比较良好,随着需要同步的数量量的增大,最近变得越来越慢。
--下面我们首先取了客户晚8点至第二天7点的awr report。

WORKLOAD REPOSITORY report for

DB Name         DB Id    Instance     Inst Num Release     RAC Host
------------ ----------- ------------ -------- ----------- --- ------------
ST990         2152526631 ST990               1 10.2.0.3.0  NO  v2011db02p

              Snap Id      Snap Time      Sessions Curs/Sess
            --------- ------------------- -------- ---------
Begin Snap:     21787 21-Feb-13 20:00:22        50      19.5
  End Snap:     21798 22-Feb-13 07:00:47        44      20.0
   Elapsed:              660.42 (mins)
   DB Time:              928.06 (mins)

--从上面的awr report 可知,单实例,10.2.0.3版本,期间的会话数也不多
--Elapsed < DB Time
--Elapsed Time=(20130222 07:00:00 - 20130221 20:00:00)≈ 660
--DB Time=928.06 ,运行环境为16核CPU, 660*16=10560, cpu花费了928.06分钟在处理Oralce非空闲等待和运算上
--从上可知,整个系统还是比较空闲

--下面来看看top event
Top 5 Timed Events                                         Avg %Total
~~~~~~~~~~~~~~~~~~                                        wait   Call
Event                                 Waits    Time (s)   (ms)   Time Wait Class
------------------------------ ------------ ----------- ------ ------ ----------
CPU time                                         20,673          37.1
log file parallel write              27,399       4,797    175    8.6 System I/O
control file parallel write          13,428       4,688    349    8.4 System I/O
log file sync                        19,564       3,795    194    6.8     Commit
db file scattered read           26,651,537       3,439      0    6.2   User I/O

--从上面的top event事件上来看,log file相关等待事件表现明显
--log file parallel write等待事件总等待次数27,399 总等待时间4,797/60=79.95(min),超出一个小时,相当可观
--其次是control file parallel write与log file sync事件的相关等待

--下面是等待事件的detail信息
Wait Events                          DB/Inst: ST1200/ST1200  Snaps: 21787-21798
-> s  - second
-> cs - centisecond -     100th of a second
-> ms - millisecond -    1000th of a second
-> us - microsecond - 1000000th of a second
-> ordered by wait time desc, waits desc (idle events last)

                                             %Time  Total Wait    wait     Waits
Event                                 Waits  -outs    Time (s)    (ms)      /txn
---------------------------- -------------- ------ ----------- ------- ---------
log file parallel write              27,399     .0       4,797     175       1.1
control file parallel write          13,428     .0       4,688     349       0.5
log file sync                        19,564   10.6       3,795     194       0.8
db file scattered read           26,651,537     .0       3,439       0   1,049.4
db file sequential read           6,682,373     .0       1,567       0     263.1
log file switch (checkpoint           1,091   92.9       1,019     934       0.0
Datapump dump file I/O              633,458     .0         286       0      24.9
log file switch completion              332   31.6         183     552       0.0
log buffer space                        255   47.8         155     608       0.0
free buffer waits                     2,409   99.5         120      50       0.1
buffer busy waits                       145   62.8          96     664       0.0


3、几个log file 事件
log file parallel write

The log file parallel write wait event has three parameters: files, blocks, and requests. In Oracle Database 10g, this wait event falls under the System I/O wait class. Keep the following key thoughts in mind when dealing with the log file parallel write wait event.

    The log file parallel write event belongs only to the LGWR process.
    A slow LGWR can impact foreground processes commit time.
    Significant log file parallel write wait time is most likely an I/O issue

 

log file sync

The log file sync wait event has one parameter: buffer#. In Oracle Database 10g, this wait event falls under the Commit wait class. Keep the following key thoughts in mind when dealing with the log file sync wait event.

    The log file sync wait event is related to transaction terminations (commits or rollbacks).

    When a process spends a lot of time on the log file sync event, it is usually indicative of too many commits or short transactions.

 

The log file switch (checkpoint incomplete) wait event has no wait parameters.

In Oracle Database 10g, this wait event falls under the Configuration wait class. Keep the following key thought in mind when dealing with the log file switch (checkpoint incomplete) wait event.

    Excessive log switches caused by small log files and a high transaction rate

更多的知识点可以参考 Oracle Wait Interface: A Practical Guide to Performance Diagnostics & Tuning

 

4、建议与解决方案
 a、从上面的分析以及日志相关等待事件的解释来看,首要的是增加日志文件的大小(200-250MB)。可参考:调整联机重做日志大小(change redo log size)
 b、日志文件组太多,建议减少到4-5组
 c、可能的情形下,将日志存放到高速磁盘(目前是raid 5上),如存放到raid 0之上
 d、采用批量提交的方式来提交事务
 e、建议增加DBWn的数目

 

更多参考:

有关Oracle RAC请参考
     使用crs_setperm修改RAC资源的所有者及权限
     使用crs_profile管理RAC资源配置文件
     RAC 数据库的启动与关闭
     再说 Oracle RAC services
     Services in Oracle Database 10g
     Migrate datbase from single instance to Oracle RAC
     Oracle RAC 连接到指定实例
     Oracle RAC 负载均衡测试(结合服务器端与客户端)
     Oracle RAC 服务器端连接负载均衡(Load Balance)
     Oracle RAC 客户端连接负载均衡(Load Balance)
     ORACLE RAC 下非缺省端口监听配置(listener.ora tnsnames.ora)
     ORACLE RAC 监听配置 (listener.ora tnsnames.ora)
     配置 RAC 负载均衡与故障转移
     CRS-1006 , CRS-0215 故障一例 
     基于Linux (RHEL 5.5) 安装Oracle 10g RAC
     使用 runcluvfy 校验Oracle RAC安装环境

有关Oracle 网络配置相关基础以及概念性的问题请参考:
     配置非默认端口的动态服务注册
     配置sqlnet.ora限制IP访问Oracle
     Oracle 监听器日志配置与管理
     设置 Oracle 监听器密码(LISTENER)
     配置ORACLE 客户端连接到数据库

有关基于用户管理的备份和备份恢复的概念请参考
     Oracle 冷备份
     Oracle 热备份
     Oracle 备份恢复概念
     Oracle 实例恢复
     Oracle 基于用户管理恢复的处理
     SYSTEM 表空间管理及备份恢复
     SYSAUX表空间管理及恢复
     Oracle 基于备份控制文件的恢复(unsing backup controlfile)

有关RMAN的备份恢复与管理请参考
     RMAN 概述及其体系结构
     RMAN 配置、监控与管理
     RMAN 备份详解
     RMAN 还原与恢复
     RMAN catalog 的创建和使用
     基于catalog 创建RMAN存储脚本
     基于catalog 的RMAN 备份与恢复
     RMAN 备份路径困惑
     使用RMAN实现异机备份恢复(WIN平台)
     使用RMAN迁移文件系统数据库到ASM
     linux 下RMAN备份shell脚本
     使用RMAN迁移数据库到异机

有关ORACLE体系结构请参考
     Oracle 表空间与数据文件
     Oracle 密码文件
     Oracle 参数文件
     Oracle 联机重做日志文件(ONLINE LOG FILE)
     Oracle 控制文件(CONTROLFILE)
     Oracle 归档日志
     Oracle 回滚(ROLLBACK)和撤销(UNDO)
     Oracle 数据库实例启动关闭过程
     Oracle 10g SGA 的自动化管理
     Oracle 实例和Oracle数据库(Oracle体系结构)

网友评论

登录后评论
0/500
评论
leshami
+ 关注