logfile优化
上一篇 / 下一篇 2020-12-22 19:42:12 / 个人分类:Linux
二、分析与方法
1、COMMIT次数过多(即图中的1-2,5-6阶段)
既然log file sync是由于commit导致的,那么commit次数过多自然会导致log file sync等待次数的增加,导致比较严重的等待。反之,如果log file sync的次数很高,但是等待的平均时间不高,则很可能是由于commit过于频繁导致的。
我们可以到数据库分析commit次数的变化量是否有突增:
--历史user commits变化情况
select * from (select snap_id,END_INTERVAL_TIME from dba_hist_snapshot order by snap_id desc) where rownum<=500;
select b.end_interval_time ,
value-lag(value,1) over(order by a.snap_id) "user commits"
from DBA_HIST_SYSSTAT a,dba_hist_snapshot b
where a.snap_id=b.snap_id and a.snap_id >=&begin_snapid and a.stat_name in('user commits')
--当前内存中commits较高的语句
SELECT SYSDATE,
SE.USERNAME,
SE.SID,
SE.SERIAL#,
SE.SQL_ID,
SE.STATUS,
SE.MACHINE,
SE.OSUSER,
ROUND(ST.VALUE) "COMMIT TIMES",
SA.SQL_TEXT
FROM V$SESSION SE, V$SESSTAT ST, V$SQLAREA SA
WHERE SE.SID = ST.SID
AND ST.STATISTIC# =
(SELECT STATISTIC# FROM V$STATNAME WHERE NAME = 'user commits')
--AND SE.USERNAME IS NOT NULL
AND ST.VALUE > 1000
AND SE.SQL_ADDRESS = SA.ADDRESS
AND SE.SQL_HASH_VALUE = SA.HASH_VALUE
ORDER BY "COMMIT TIMES" DESC;
如果commit次数过多,则建议解决异常commit语句,考虑合并commit
2、IO性能问题(即图中的3-4阶段)
概述的最后面有说明到,可以与log file parallel write进行比较:
如果log file sync突增期间,log file parallel write也突增,则很可能是IO问题导致。可以排查这几个方面:
(1)存储端整体性能问题(这就不多解释了,通常都建议使用IO性能较好存储,而且是写性能优先)
(2)IO尖刺:如果log file parallel write的等待时间比较高,而log file sync的平均等待时间恰好在正常的I/O范围内,请注意这可能是因为I/O中存在峰值,而平均值是没法显示出来的,这种情况就可以借助等待事件直方图,或者直接看AWR、OSWatcher等来进行分析。
(3)高IO消耗sql/应用(导致IO瓶颈,自然整体效率下降):分析服务器,是什么导致了高IO消耗。大部分数据库服务器只有数据库,所以一般情况下都是SQL导致的。
(4)IO争用:redolog和其他文件防止一起,存在IO争用。此时就建议将online redo log分离出来,放到独立的磁盘上。
--iowait 检查log file sync、log file parallel write以及各类等待事件的耗时
with t as (
select s.snap_id,
s.instance_number,
s.end_interval_time,
total_waits - lag(total_waits, 1) over(partition by s.instance_number order by s.snap_id) waits,
(time_waited_micro - lag(time_waited_micro, 1) over(partition by s.instance_number order by s.snap_id)) / 1000 twt
from dba_hist_system_event ev, dba_hist_snapshot s
where ev.instance_number = s.instance_number
and ev.snap_id = s.snap_id
and event_name = 'log file sync' --带入所需的等待事件名
and s.end_interval_time BETWEEN sysdate - 3 AND sysdate)
select to_char(end_interval_time, 'YYYYMMDD HH24:MI'),
instance_number,
sum(waits),
sum(twt),
round(sum(twt) / sum(waits), 2) wt
from t
group by to_char(end_interval_time, 'YYYYMMDD HH24:MI'), instance_number
order by 1, instance_number;
--iowait直方图 检查各类等待事件在对应毫秒区间的触发次数
select b.end_interval_time,
sum(decode(a.wait_time_milli,1,a.wait_count,null))-sum(decode(c.wait_time_milli,1,c.wait_count,null)) wait_time_milli_1,
sum(decode(a.wait_time_milli,2,a.wait_count,null))-sum(decode(c.wait_time_milli,2,c.wait_count,null)) wait_time_milli_2,
sum(decode(a.wait_time_milli,4,a.wait_count,null))-sum(decode(c.wait_time_milli,4,c.wait_count,null)) wait_time_milli_4,
sum(decode(a.wait_time_milli,8,a.wait_count,null))-sum(decode(c.wait_time_milli,8,c.wait_count,null)) wait_time_milli_8,
sum(decode(a.wait_time_milli,16,a.wait_count,null))-sum(decode(c.wait_time_milli,16,c.wait_count,null)) wait_time_milli_16,
sum(decode(a.wait_time_milli,32,a.wait_count,null))-sum(decode(c.wait_time_milli,32,c.wait_count,null)) wait_time_milli_32,
sum(decode(a.wait_time_milli,64,a.wait_count,null))-sum(decode(c.wait_time_milli,64,c.wait_count,null)) wait_time_milli_64,
sum(decode(a.wait_time_milli,128,a.wait_count,null))-sum(decode(c.wait_time_milli,128,c.wait_count,null)) wait_time_milli_128,
sum(decode(a.wait_time_milli,256,a.wait_count,null))-sum(decode(c.wait_time_milli,256,c.wait_count,null)) wait_time_milli_256,
sum(decode(a.wait_time_milli,512,a.wait_count,null))-sum(decode(c.wait_time_milli,512,c.wait_count,null)) wait_time_milli_512,
sum(decode(a.wait_time_milli,1024,a.wait_count,null))-sum(decode(c.wait_time_milli,1024,c.wait_count,null)) wait_time_milli_1024,
sum(decode(a.wait_time_milli,2048,a.wait_count,null))-sum(decode(c.wait_time_milli,2048,c.wait_count,null)) wait_time_milli_2048,
sum(decode(a.wait_time_milli,4096,a.wait_count,null))-sum(decode(c.wait_time_milli,4096,c.wait_count,null)) wait_time_milli_4096,
sum(decode(a.wait_time_milli,8192,a.wait_count,null))-sum(decode(c.wait_time_milli,8192,c.wait_count,null)) wait_time_milli_8192
from dba_hist_event_histogram a ,dba_hist_snapshot b,dba_hist_event_histogram c
where a.event_name='log file sync' and a.snap_id=b.snap_id --带入所需的等待事件名
and b.end_interval_time BETWEEN sysdate - 3 AND sysdate
and a.snap_id=c.snap_id + 1
and a.wait_time_milli=c.wait_time_milli
and a.event_name=c.event_name
group by b.end_interval_time
order by end_interval_time desc;
3、日志/日志量问题(全面阶段)
(1)redo log 大小/组数量不合理,一般伴随着各类log file switch等待
(2)异常SQL语句导致了大量的日志生成:
日志量激增,导致日志频繁切换(一般同样伴随着各类log file switch等待)。而日志切换期间无法写日志,又阻塞commit引起的日志写,所以之前的1,2步变慢。
日志切换期间lgwr要做更多的工作,比如通知arch进行归档,从控制文件中找出新日志组,打开新的日志组,在新日志组中写入初始化信息等等,导致3-5步变慢,总体自然更慢
4、log buffer问题(全面阶段)
log buffer不足:
(1)前台进程需要等待lgwr释放log buffer才能继续分配。
(2)log buffer较小也会导致频繁的日志写操作
5、隐含参数问题(lgwr工作机制问题)
ORACLE从11gR2开始,为lgwr写日志引入了polling机制,而在以前只有post/wait机制。【官方文档说明请参考:Adaptive Log File Sync Optimization (Doc ID 1541136.1)】
同时引入了一个隐含参数,“_use_adaptive_log_file_sync”即通过定义该参数来确定使用哪个机制。
在11.2.0.3以下,该参数的默认值为false,即只启用post/wait机制。
从11.2.0.3开始,该参数的默认值为true,即ORACLE会在post/wait和polling机制之间自适应切换。
Post/wait机制下:lgwr执行写入操作完成后,会立刻通知前台进程已经写入完成,因此log file sync等待时间短,但lgwr/cpu的负担会稍重一点。
Polling机制下:lgwr执行写入操作完成后,不再通知前台进程已经写入完成。而前台进程会sleep并timeout后去检查log buffer中的内容是否被写入了磁盘。该机制下,解放了一部分lgwr的工作,并节约CPU资源,但是会导致待commit的进程较长时间处于log file sync等待下。
查看隐含参数值:
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');
--我们可以在lgwr进程的trace文件中看到一些切换记录:
cd $ORACLE_BASE/diag/rdbms/$DB_UNIQUE_NAME/$ORACLE_SID/trace
ls -ltr | grep lgwr
egrep -i "polling|post" bspdb_lgwr_29068.trc
Log file sync switching to polling 或者 Log file sync switching to post/wait
建议:在11.2.0.3.0以及后续的版本上,调整该参数,设置为false:
alter system set "_use_adaptive_log_file_sync"=false;
6、CPU问题
在网上甚至不少书里,都把log file sync等待的责任推到IO问题上。在大多数情况下,这样的推断是没有问题的,不过并不能一概而论。从一开始官方文档以及我们分析得出的6个阶段和图表来看,log file sync也是很依赖CPU资源的。这里为了证明这个理论,再次引用上面举例出来官方文档的那句话“The surplus time is CPU activity and is most commonly contention caused by over committing.”
个人认为这句话最重要的并不是后面那段“大部分是由于过量commit导致的”。而应该是前面那一句“(排除IO消耗的时间后,log file sync等待的)剩余时间是CPU的动作”。这就表明了CPU也是造成log file sync慢的一个重要原因,只不过commit次数太多在这种场景下比较显眼而已。
(1)CPU资源瓶颈:比如load average较高(top命令),CPU使用率较高(top命令)、CPU运行队列过长(vmstat命令)。导致了进程间的通信、调度延迟。
检查导致CPU瓶颈的原因,到底是硬件问题,还是业务(大部分情况下应该都是SQL)导致。然后根据结论反馈问题给对应的人员进行处理(硬件厂商/应用研发)
(2)lgwr优先级不够:_high_priority_processes隐含参数,或者$ORACLE_HOME/bin/oradism文件属主和权限异常(一般是由于root.sh未执行/执行出错),都会影响lgwr进程是否可以运行在高优先级。
正确权限/属主为:
cnsz17pl7300:fina > ls -l $ORACLE_HOME/bin/oradism
-rwsr-x--- 1 root oinstall 71758 Sep 17 2011 /dba/oracle/product/11.2.0.3.15/bin/oradism
7、其他场景/优化
(1)参数commit_logging:了解即可,极不推荐修改。类似mysql的双1模式。
(2)BUG,略。。。
三、实际案例
1、问题排查
值班期间收到告警:bspdb库很多行锁等待enq: TX - row lock contention
但是检查发现,很多行锁等待确实有问题。但是更为严重的是log file sync。
20:27:03 sf01396777@bspdb> @event
EVENT COUNT(*)
--------------------------------------------------- -------------
SQL*Net message from client 1520
log file sync 235
rdbms ipc message 29
enq: TX - row lock contention 19
发现异常等待事件中,大量都在等待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当中,如下所示。
cnsz17pl1323:bspdb > pwd
/dba/oracle/diag/rdbms/bspdb/bspdb/trace
cnsz17pl1323:bspdb > ls -ltr | grep lgwr
-rw-r----- 1 oracle oinstall 160284 Aug 10 20:49 bspdb_lgwr_29068.trm
-rw-r----- 1 oracle oinstall 804848 Aug 10 20:49 bspdb_lgwr_29068.trc
cnsz17pl1323:bspdb >
cnsz17pl1323:bspdb >
cnsz17pl1323:bspdb > egrep -i "polling|post" bspdb_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对 fina 库进行变更: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、后续
fina库调整后效果显著且稳定,随即对bspdb库也进行隐含参数优化。
不过得到的效果并没有fina库那么显著,提升只在5%-10%之间。虽然效果没有预期的大,但也证明这个操作是有一定效果的。不过这个系统整理压力较大,并非是一个简单参数就能做到优化成功的,还需要配合业务SQL调整优化。
相关阅读:
- Oracle批量创建表空间 (zaza9084, 2018-2-23)
- Oracle存储过程和自定义函数 (zaza9084, 2018-3-30)
- Oracle系统数据复制技术?这里为你详解一下~ (资深梦游, 2018-4-12)
- 细说Oracle数据库与操作系统存储管理二三事 (资深梦游, 2018-4-16)
- Oracle JOB异常中断原因分析 (资深梦游, 2018-4-26)
- Oracle 毙掉 JavaOne,以 Oracle Code One 取而代之 (资深梦游, 2018-4-28)
- Oracle声称它可以将云迁移成本将低30%,但客户会买账吗? (资深梦游, 2018-6-11)
- 详解Oracle数据库主键SYS_GUID() (旺达, 2019-9-06)
标题搜索
日历
|
|||||||||
日 | 一 | 二 | 三 | 四 | 五 | 六 | |||
1 | 2 | 3 | 4 | 5 | 6 | ||||
7 | 8 | 9 | 10 | 11 | 12 | 13 | |||
14 | 15 | 16 | 17 | 18 | 19 | 20 | |||
21 | 22 | 23 | 24 | 25 | 26 | 27 | |||
28 | 29 | 30 |
我的存档
数据统计
- 访问量: 189743
- 日志数: 55
- 图片数: 4
- 文件数: 3
- 建立时间: 2010-11-29
- 更新时间: 2020-12-24