【DBA笔记7】log file sync等待事件案例（一）

目录

1、问题排查

2、优化建议

3、变更完成后复查

4、后续

---

1、问题排查

某天收到告警：testdb库很多log file sync等待

20:27:03 mytest@testdb> @event

EVENT                                                COUNT(*)
---------------------------------------------------  -------------
SQL*Net message from client                          1520
log file sync                                        235
rdbms ipc message                                    29
enq: TX - row lock contention                        12

发现异常等待事件中，大量都在等待log file parallel write和log file sync
检查iowait、log_buffer、redolog和commit次数发现：log file sync并非是由于io性能导致的，而是CPU问题，而CPU调度可以细化下去，大致分为几项：

（1）commit频率过量

检查高频commit的语句，反馈研发整改。

（2）cpu资源瓶颈

检查cpu使用率：平均20%，高峰期40%

cpu运行队列：平均30，高峰期150

高消耗SQL：略。。。

（3）lgwr进程优先级问题

检查操作系统与数据库参数（若变更则影响较大，风险较高，方案待定）

（4）隐含参数导致进程调度模式变化有关系：_use_adaptive_log_file_sync

lgwr模式之间的切换会记录到lgwr进程的trace当中，如下所示。

testhost:testdb > pwd
/u01/oracle/diag/rdbms/testdb/testdb/trace
testhost:testdb > ls -ltr | grep lgwr
-rw-r----- 1 oracle oinstall   160284 Aug 10 20:49 testdb_lgwr_29068.trm
-rw-r----- 1 oracle oinstall   804848 Aug 10 20:49 testdb_lgwr_29068.trc
testhost:testdb > 
testhost:testdb > 
testhost:testdb > egrep -i "polling|post" testdb_lgwr_29068.trc
kcrfw_update_adaptive_sync_mode: post->poll long#=3177 sync#=25097 sync=5553 poll=2150 rw=1075 rw+=4192 ack=0 min_sleep=1073
Log file sync switching to polling
kcrfw_update_adaptive_sync_mode: poll->post current_sched_delay=0 switch_sched_delay=1 current_sync_count_delta=7675 switch_sync_count_delta=25097
Log file sync switching to post/wait
kcrfw_update_adaptive_sync_mode: post->poll long#=2507 sync#=14491 sync=5983 poll=2904 rw=1452 rw+=1452 ack=0 min_sleep=1073
Log file sync switching to polling
kcrfw_update_adaptive_sync_mode: poll->post current_sched_delay=0 switch_sched_delay=1 current_sync_count_delta=6632 switch_sync_count_delta=14491
Log file sync switching to post/wait
kcrfw_update_adaptive_sync_mode: post->poll long#=3190 sync#=23329 sync=6219 poll=4098 rw=2049 rw+=2049 ack=0 min_sleep=1073
Log file sync switching to polling
kcrfw_update_adaptive_sync_mode: poll->post current_sched_delay=0 switch_sched_delay=1 current_sync_count_delta=10829 switch_sync_count_delta=23329
Log file sync switching to post/wait
kcrfw_update_adaptive_sync_mode: post->poll long#=1804 sync#=4233 sync=149590 poll=34934 rw=17467 rw+=17472 ack=0 min_sleep=1073
Log file sync switching to polling
kcrfw_update_adaptive_sync_mode: poll->post current_sched_delay=0 switch_sched_delay=1 current_sync_count_delta=1805 switch_sync_count_delta=4233
Log file sync switching to post/wait
kcrfw_update_adaptive_sync_mode: post->poll long#=4891 sync#=33191 sync=4212 poll=3712 rw=1856 rw+=1856 ack=0 min_sleep=1073

查看隐含参数：

SQL> select a.ksppinm name,b.ksppstvl value, a.ksppdesc description from x$ksppi a, x$ksppcv b where a.indx = b.indx and a.ksppinm in ('_use_adaptive_log_file_sync');

NAME                           VALUE    DESCRIPTION
------------------------------ -------- ------------------------------------------------
_use_adaptive_log_file_sync    TRUE     Adaptively switch between post/wait and polling

log file parallel write耗时：单位毫秒

log file sync耗时：单位毫

 
commit次数：

user calls/(user commits + user rollbacks) 比较低
说明commit频率占用户调用次数比重较高

2、优化建议

（1）反馈高频commit语句与高消耗SQL（包括cpu和日志量）语句到研发整改优化
（2）调整_use_adaptive_log_file_sync参数为false。
（3）待隐含参数效果明确后，逐步下发到所有oracle 11.2.0.3.0 及以上版本的数据库中，减少log file sync等待对性能的影响。
（4）调整新建库标准手册/自动化任务，将该隐含参数默认调整为false，做到从数据库规范初始化与交付工作中就提前预防这类问题。

由于该库重要程度很高，随即找一个log file sync也比较高，但即将下线且重要性不太高的库进行变更操作：

2020-09-10 10:30 对 oratest 库进行变更：

alter system set "_use_adaptive_log_file_sync"=false;

 

3、变更完成后复查

log file sync等待耗时：单位毫秒

log file sync等待出现次数：

调整完成后的结果如下：

log file sync    优化前    优化后
平均等待耗时    6ms    3ms
平均等待并发    140次/天    70次/天

根据优化前后的性能对比，以及稳定性来看。该参数效果显著且稳定，可逐步调整到log file sync压力比较大的库中并调整标准化建库手册/自动化任务。

4、后续

oratest库调整后效果显著且稳定，随即对testdb库也进行隐含参数优化。

不过得到的效果并没有fina库那么显著，提升只在5%-10%之间。虽然效果没有预期的大，但也证明这个操作是有一定效果的。不过这个系统整理压力较大，并非是一个简单参数就能做到优化成功的，还需要配合业务SQL调整优化。