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

本文涉及的产品
网络型负载均衡 NLB,每月750个小时 15LCU
日志服务 SLS,月写入数据量 50GB 1个月
传统型负载均衡 CLB,每月750个小时 15LCU
简介:       Oracle 联机重做日志文件记录了数据库的所有变化(DML,DDL或管理员对数据所作的结构性更改等),用于对于意外删除或宕机利用日志文件实现数据恢复来确保数据的完整性。

      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体系结构)

相关实践学习
日志服务之使用Nginx模式采集日志
本文介绍如何通过日志服务控制台创建Nginx模式的Logtail配置快速采集Nginx日志并进行多维度分析。
目录
相关文章
|
2月前
|
存储 Oracle 关系型数据库
【赵渝强老师】MySQL InnoDB的数据文件与重做日志文件
本文介绍了MySQL InnoDB存储引擎中的数据文件和重做日志文件。数据文件包括`.ibd`和`ibdata`文件,用于存放InnoDB数据和索引。重做日志文件(redo log)确保数据的可靠性和事务的持久性,其大小和路径可由相关参数配置。文章还提供了视频讲解和示例代码。
180 11
【赵渝强老师】MySQL InnoDB的数据文件与重做日志文件
|
2月前
|
SQL Oracle 关系型数据库
【赵渝强老师】Oracle的控制文件与归档日志文件
本文介绍了Oracle数据库中的控制文件和归档日志文件。控制文件记录了数据库的物理结构信息,如数据库名、数据文件和联机日志文件的位置等。为了保护数据库,通常会进行控制文件的多路复用。归档日志文件是联机重做日志文件的副本,用于记录数据库的变更历史。文章还提供了相关SQL语句,帮助查看和设置数据库的日志模式。
【赵渝强老师】Oracle的控制文件与归档日志文件
|
2月前
|
SQL 关系型数据库 MySQL
【赵渝强老师】MySQL的全量日志文件
MySQL全量日志记录所有操作的SQL语句,默认禁用。启用后,可通过`show variables like %general_log%检查状态,使用`set global general_log=ON`临时开启,执行查询并查看日志文件以追踪SQL执行详情。
|
2月前
|
Oracle 关系型数据库 数据库
【赵渝强老师】Oracle的参数文件与告警日志文件
本文介绍了Oracle数据库的参数文件和告警日志文件。参数文件分为初始化参数文件(PFile)和服务器端参数文件(SPFile),在数据库启动时读取并分配资源。告警日志文件记录了数据库的重要活动、错误和警告信息,帮助诊断问题。文中还提供了相关视频讲解和示例代码。
|
2月前
|
存储 Oracle 关系型数据库
【赵渝强老师】MySQL的撤销日志文件和错误日志文件
本文介绍了MySQL的物理存储结构,重点讲解了InnoDB存储引擎中的撤销日志文件(undo log)和错误日志文件。从MySQL 8.0开始,默认生成两个10MB的undo表空间文件,并支持动态扩容和收缩。错误日志文件记录了MySQL启动、运行、关闭过程中的问题,通过示例展示了如何查看和使用这些日志。
|
3月前
|
SQL 数据库
为什么 SQL 日志文件很大,我应该如何处理?
为什么 SQL 日志文件很大,我应该如何处理?
|
2月前
|
XML 安全 Java
【日志框架整合】Slf4j、Log4j、Log4j2、Logback配置模板
本文介绍了Java日志框架的基本概念和使用方法,重点讨论了SLF4J、Log4j、Logback和Log4j2之间的关系及其性能对比。SLF4J作为一个日志抽象层,允许开发者使用统一的日志接口,而Log4j、Logback和Log4j2则是具体的日志实现框架。Log4j2在性能上优于Logback,推荐在新项目中使用。文章还详细说明了如何在Spring Boot项目中配置Log4j2和Logback,以及如何使用Lombok简化日志记录。最后,提供了一些日志配置的最佳实践,包括滚动日志、统一日志格式和提高日志性能的方法。
773 31
【日志框架整合】Slf4j、Log4j、Log4j2、Logback配置模板
|
1月前
|
监控 安全 Apache
什么是Apache日志?为什么Apache日志分析很重要?
Apache是全球广泛使用的Web服务器软件,支持超过30%的活跃网站。它通过接收和处理HTTP请求,与后端服务器通信,返回响应并记录日志,确保网页请求的快速准确处理。Apache日志分为访问日志和错误日志,对提升用户体验、保障安全及优化性能至关重要。EventLog Analyzer等工具可有效管理和分析这些日志,增强Web服务的安全性和可靠性。
|
3月前
|
XML JSON Java
Logback 与 log4j2 性能对比:谁才是日志框架的性能王者?
【10月更文挑战第5天】在Java开发中,日志框架是不可或缺的工具,它们帮助我们记录系统运行时的信息、警告和错误,对于开发人员来说至关重要。在众多日志框架中,Logback和log4j2以其卓越的性能和丰富的功能脱颖而出,成为开发者们的首选。本文将深入探讨Logback与log4j2在性能方面的对比,通过详细的分析和实例,帮助大家理解两者之间的性能差异,以便在实际项目中做出更明智的选择。
417 3
|
20天前
|
SQL 关系型数据库 MySQL
MySQL事务日志-Undo Log工作原理分析
事务的持久性是交由Redo Log来保证,原子性则是交由Undo Log来保证。如果事务中的SQL执行到一半出现错误,需要把前面已经执行过的SQL撤销以达到原子性的目的,这个过程也叫做"回滚",所以Undo Log也叫回滚日志。
MySQL事务日志-Undo Log工作原理分析