性能优化之高Log file sync等待实战案例分享

淩亂°似流年 2024-03-16 12:05 49阅读 0赞

## 故障情况 ##

AWR报告如下：

![35d209e9ed3a49908b73b690a4e6fa0b.png][]

![6b6aa9168db448db926b1d70173be6f4.png][]

![8cba0d9125594b3b8b5d253d90ce1f8e.png][]

![9c866e121e1f4d6c87c1198e5d572162.png][]

![02e12d76e8f046a8a3f2f866c9141410.png][]

之后他们把大部分业务停掉后，Log file sync等待事件还是非常高。

通过对比昨天跟今天相同时间的AWR，在业务量小非常多的情况，等待时间还是高非常大。

![9d4944c0c54f4437a49313115dfe2fb5.png][]

![280c6a9b07224f9da14a893b3e6ee2c4.png][]

## 诊断过程 ##

log file sync等待事件首先判断当前系统IO是否存在问题，看操作系统日志没有相关的报错，执行IO测试，也显示IO处于正常状态，详细查看AWR报告，AWR显示数据库写IO及读IO都还比较正常。对比昨天跟今天的AWR报告，也可以看出IO读写性能跟昨天相比差别不大，今天采集的这个时间段由于停了大部分业务，IO相比昨天反而更优，但是日志切换的等待时间反而要增加8秒。

![7ed021b7ddcb4a15a32b24245e725833.png][]

![2f1dffa6bdf84d5c8ab5a9965f923d72.png][] 根据Tanel Poder前辈写的《Log file sync,LGWR》诊断手册里的Commit log file sync flow

![46e5e0b6d3f44dd6b74f0ca814d45d06.png][]

从上图中，我们可以清楚的看到commit整个流程。

1、当user发起一个commit后；

2、前端进程（即Server 进程）会post一个信息给lgwr进程，告诉它去写redo buffer。

3、当LGWR进程得到指示后，开始调用操作系统函数进行物理写，在进行物理写的这段时间内，会出现log file parallel write等待。

4、当LGWR完成wrtie操作之后，LGWR进程会返回一个信息给前端进程（Server进程），告诉它，我已经写完了，你可以完成提交了。

5. user 完成commit操作。

从上面的流程图，结合AWR 里log file parallel write及用户IO及系统IO的等待时间都很短，因此我们可以判断问题不是出在IO性能上。那么问题应该出在阶段2及阶段5上。

根据mos文章：

《**Troubleshooting: 'Log file sync' Waits (Doc ID 1376916.1)****》**

**《****Adaptive Log File Sync Optimization (Doc ID 1541136.1)****》**

**《****Adaptive Switching Between Log Write Methods can Cause 'log file sync' Waits (Doc ID 1462942.1)****》**

发现Oracle11g 之后Oracle新推出一种日志同步方式，称为自适应方式，在Oracle 11.2.0.3版本之后启用这个特性

![9d5f53c016c04c02b54dc99da264de2c.png][]

Initially the LGWR uses post/wait and according to an internal algorithm evaluates whether polling is better. Under high system load polling may perform better because the post/wait implementation typically does not scale well. If the system load is low, then post/wait performs well and provides better response times than polling. Oracle relies on internal statistics to determine which method should be used. Because switching between post/wait and polling incurs an overhead, safe guards are in place in order to ensure that switches do not occur too frequently.

根据文单的描述，检查系统的负载情况，发现今天业务系统在14点时负载很高，日志切换达136次，之后业务恢复正常

![9ecc388c59134e8d80415b86388d100a.png][]

检查当前的系统，发现当前系统LGWR正采用Polling方式。

SQL> select name,value from v$sysstat where name in ('redo synch poll writes','redo synch polls');

redo synch poll writes 6248

redo synch polls 8843

## 故障原因分析 ##

由于业务系统在14点时负载变为非常高，因此Oracle把LGWR写方式切换为Polling方式，以保持更高的性能，但是当业务负载降下来时，正常情况下LGWR应该切换回原有Post/wait 方式，但是这次没有切换，还一直采用Polling方式。判断碰到BUG，没有切换，因此导致性能变差(网上文章写polling的间隔是10ms，Post/wait 的间隔是1~2ms，在mos上没找到文章有写这个时间)

相关的BUG:

![8868264676fa4854aa2c52697c472430.png][]

在11.2.03版本上可以应用[DATABASE PATCH SET UPDATE 11.2.0.3.14 (INCLUDES CPUAPR2015)][DATABASE PATCH SET UPDATE 11.2.0.3.14 _INCLUDES CPUAPR2015]解决这个BUG。

## 解决方案 ##

**Workaround**

Disable adaptive log file sync by setting "\_use\_adaptive\_log\_file\_sync"=false

ALTER SYSTEM SET "\_use\_adaptive\_log\_file\_sync"=FALSE ;

或者重启实例也可以解决。

[35d209e9ed3a49908b73b690a4e6fa0b.png]: https://image.dandelioncloud.cn/pgy_files/images/2024/03/16/b62094956cf3412c9b1cb68281182d90.png
[6b6aa9168db448db926b1d70173be6f4.png]: https://image.dandelioncloud.cn/pgy_files/images/2024/03/16/767512d3ce244f95a1624eb83d3e17ad.png
[8cba0d9125594b3b8b5d253d90ce1f8e.png]: https://image.dandelioncloud.cn/pgy_files/images/2024/03/16/f0c486832b3041ee859c1c7d1c596a31.png
[9c866e121e1f4d6c87c1198e5d572162.png]: https://image.dandelioncloud.cn/pgy_files/images/2024/03/16/0008c36a85d94dd482e4d1c5348ba96a.png
[02e12d76e8f046a8a3f2f866c9141410.png]: https://image.dandelioncloud.cn/pgy_files/images/2024/03/16/c82914a1f5054da99b52762459942790.png
[9d4944c0c54f4437a49313115dfe2fb5.png]: https://image.dandelioncloud.cn/pgy_files/images/2024/03/16/22ccc3d9ef4b4b1b9b8a4b50dfc15ac1.png
[280c6a9b07224f9da14a893b3e6ee2c4.png]: https://image.dandelioncloud.cn/pgy_files/images/2024/03/16/970cf720eb8d401993e422ac792439e9.png
[7ed021b7ddcb4a15a32b24245e725833.png]: https://image.dandelioncloud.cn/pgy_files/images/2024/03/16/d03d1c04969041439f78fdaf1cf1bdc6.png
[2f1dffa6bdf84d5c8ab5a9965f923d72.png]: https://image.dandelioncloud.cn/pgy_files/images/2024/03/16/c5ff4af321814a98b834fae992def7b4.png
[46e5e0b6d3f44dd6b74f0ca814d45d06.png]: https://image.dandelioncloud.cn/pgy_files/images/2024/03/16/7077572948674c45a7a28b9bd499b69e.png
[9d5f53c016c04c02b54dc99da264de2c.png]: https://image.dandelioncloud.cn/pgy_files/images/2024/03/16/66550c3de5ff496a8e220d6f891e32e1.png
[9ecc388c59134e8d80415b86388d100a.png]: https://image.dandelioncloud.cn/pgy_files/images/2024/03/16/5490f15675f44b7692bb3e5f51df96e7.png
[8868264676fa4854aa2c52697c472430.png]: https://image.dandelioncloud.cn/pgy_files/images/2024/03/16/6ef62dbeac1e4ffb96891aaf17f45488.png
[DATABASE PATCH SET UPDATE 11.2.0.3.14 _INCLUDES CPUAPR2015]: https://support.oracle.com/epmos/faces/PatchResultsNDetails?_adf.ctrl-state=30oj9xvto_292&releaseId=80112031403&requestId=18682005&patchId=13074706&languageId=0&platformId=226&searchdata=%3Ccontext+type%3D%22BASIC%22+search%3D%22%26lt%3BSearch%26gt%3B%26lt%3BFilter+name%3D%26quot%3Bpatch_number%26quot%3B+op%3D%26quot%3Bis%26quot%3B+value%3D%26quot%3B13074706%26quot%3B%2F%26gt%3B%26lt%3B%2FSearch%26gt%3B%22%2F%3E&_afrLoop=452651744335481