log file sync致数据库性能摇摆

数据库在某些时间点突然出现性能峰值，使得前端应用程序有停滞感。分析出为log file sync 事件突然发生导致了该问题。

该事件是表示用户在LWGR 进程将redo 日志信息写入的redo logfile 。在普通的数据库配置中，能优化这个问题的方法只能减低日志写入量，提升日志写入速度，就是将redo logfile 放到更快的磁盘组上。

我们这里的数据库环境是LGWR 既要将REDO 日志信息写入到REDO 日志文件中，也要通过网络写入到远程的STANDBY 数据库中。

我们的问题出现在写入到standby 时发生了堵塞，导致了log file sync 等待事件的大量发生，从而使得数据库性能峰值频繁出现，有时候都影响到应用。

因此我们将LGWR 写入到standby 的操作方式从lgwr sync affirm 修改为lgwr async 方式，就是从实时同步修改为非实时同步。

这样就解决了这个性能问题。

 

(miki西游 @mikixiyou 原文链接: http://mikixiyou.iteye.com/blog/1570147 )

 

1.  问题

环境交代一下，数据库版本10.2.0.4 ，ASM 存储，单实例，归档模式，多路径用于异地的data guard 逻辑备库和物理备库，最大可用模式。

在Oracle EM GRID CONTROL 管理平台中，看到数据库性能页面上平均活动会话瞬间提升到数倍，如正常时一直是2-3 个，到某个时间点到达18-19 个之多。

突然增加的等待事件归类为configuration 和concurrency 。在configuration 类中，等待事件为log file sync 。

这个等待事件的发生导致很多会话出现堵塞，反映到应用端就是应用停滞。

我们再到awrrpt 报告中，也能看到top 5 等待事件以log file sync 居首。

Top 5 Timed Events

Event	Waits	Time(s)	Avg Wait(ms)	% Total Call Time	Wait Class
log file sync	256,569	66,039	257	86.4	Commit
CPU time		4,308		5.6
enq: TX - row lock contention	4,894	4,140	846	5.4	Application
log file switch completion	1,817	1,485	817	1.9	Configuration
LNS wait on SENDREQ	350,286	464	1	.6	Network

这个更具体，以数字形式直接展现出来，等待事件log file sync 的问题何其严重。

统计时间30 分钟，等待事件log file sync 使用66039 秒，整个86.4% 的时间都是log file sync 消耗的。

性能问题很明显，在log file sync 等待事件上。解决掉它，就能解决这个应用摇摆问题。

2.  分析

等待事件log file sync 是这样产生的。

当一个用户提交(commits) 或者回滚(rollback), 会话的redo 信息需要写出到redo logfile 中。用户进程将通知LGWR 执行写出操作,LGWR 完成任务以后会通知用户进程。等待事件log file sync 就是指用户进程等待LGWR 的写完成通知。

但是，这只是正常的配置下的生成过程。在我们的环境中，LGWR 还需要将redo 信息写入到网络上其他的数据库服务器中。

这是因为这台服务器配置了两台standby database 服务器：一台用于查询库实时同步数据；一台用于数据灾备镜像库，也是要实时同步。

因为实时同步需要，所以写redo 信息的参数项是lgwr sync 。具体参数配置如下所示：

*.log_archive_dest_2='service=mikidb_reader lgwr sync affirm  valid_for=(online_logfiles,primary_role) db_unique_name=mikidg'

*.log_archive_dest_3='service=mikidb_standby2 lgwr sync affirm  valid_for=(online_logfiles,primary_role) db_unique_name=mikidg2'

 

 

所以，问题在LGWR 写redo 信息到磁盘上还是网络上发生了堵塞导致了性能峰值，需要我们去判断一下。

如果是发生在写入磁盘上导致了性能峰值问题，那我们也没办法了。更快的磁盘真的没有了。

如果是发生在网络上，我们需要检查网络状况。

但这里还有一种可能，就是redo 信息的量在那个时间点真的突然增大了。这种情况也是有可能导致这种性能峰值问题。

但这个可能很快被否决掉，在awrrpt 中load profile 项看到, 每秒生成的redo 日志并没有多大变化，一直维持在200KB 略多点。

 

 

3.  解决

问题分析到这里，解决方法其实很简单了。

检查网络情况，在网络情况不确定之前，我们可以先将这两个写入standby 的操作关闭掉。

这个有点武断，哈哈。

在10.2 中，LGWR 写入redo 信息到standby 数据库中有两个方式：一种是lgwr sync ，另一种lgwr async 。

前者是保证数据必须同步过去，LNS 进程传redo 信息到standby 数据库时必须给回复，不给则不显示提交成功。

这点可以参考一下eygle 的文档中描述， http://www.eygle.com/archives/2004/10/statspack14-logfilesync.html

后者是先保证写入到本地redo logfile 中，剩下的交给LNS 进程，它接着做下面的事情。这样LNS 能否能redo 信息及时写入到standby 数据库就只有看天意了。

第二种方法虽然不好，但还是比没有强。因此，我们选择它先来解决这个问题。

数据库初始化参数设置如下所示：

*.log_archive_dest_2='service=mikidb_reader lgwr async valid_for=(online_logfiles,primary_role) db_unique_name=mikidg'

*.log_archive_dest_3='service=mikidb_standby2 lgwr async valid_for=(online_logfiles,primary_role) db_unique_name=mikidg2'

如果网络检查有问题，那么修复后我们可以再改回为lgwr sync ，不行再改回lgwr async 。

 

4.  总结

我们将参数修改后观察了一下，发现活动会话很稳定，等待事件也都是CPU 处理事件。

 

在awrrpt 中，可以看到具体的数字。

Top 5 Timed Events

Event	Waits	Time(s)	Avg Wait(ms)	% Total Call Time	Wait Class
CPU time		4,192		98.0
log file sync	153,941	23	0	.5	Commit
LNS wait on SENDREQ	289	14	48	.3	Network
enq: TX - row lock contention	1,031	11	11	.3	Application
log file parallel write	157,352	9	0	.2	System I/O

 

我们对比一下。

这是修改之前的等待事件log file sync 统计信息：

Event	Waits	Time(s)	Avg Wait(ms)	% Total Call Time	Wait Class
log file sync	256,569	66,039	257	86.4	Commit

 

这是修改之后的等待事件log file sync 统计信息：

Event	Waits	Time(s)	Avg Wait(ms)	% Total Call Time	Wait Class
log file sync	153,941	23	0	.5	Commit

 

等待次数下降的不大，等待时间下降了3000 倍啊。

因此，在碰到这台硬的等待事件时，不能光看一些官文中描述，还要结合环境具体看待。

但它也有局限，主数据库的数据不会真的实时同步到standby 数据库里了。数据的安全有一些损失，但在性能、可用性、数据安全方面，是必须有取舍的。

评论

1 楼 szkktom 2012-08-02  

觉得 oracle牛人好多，对oracle 理解好深刻啊，
身边高手好少