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优化前优化后
平均等待耗时6ms3ms
平均等待并发140次/天70次/天



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



4、后续

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

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





TAG: Oracle oracle

 

评分:0

我来说两句

显示全部

:loveliness: :handshake :victory: :funk: :time: :kiss: :call: :hug: :lol :'( :Q :L ;P :$ :P :o :@ :D :( :)

日历

« 2021-01-18  
     12
3456789
10111213141516
17181920212223
24252627282930
31      

数据统计

  • 访问量: 171395
  • 日志数: 55
  • 图片数: 4
  • 文件数: 3
  • 建立时间: 2010-11-29
  • 更新时间: 2020-12-24

RSS订阅

Open Toolbar