目录
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调整优化。