ANBOB™

最近一周遇到2例LGWR/CKPT 等待的问题，但这类问题往往只从top event分析容易走入误区，如显示top event是Log file switch (checkpoint incomplete) 或Log file switch或enq: CF – contention ,或是一个IDLE类的rdbms ipc message等待, 有时会在db alert log中显示ckpt has not moved for N sec等，建议先确认当时的IO系统是否正常。

我的blog之前有记录过案例片段
案例: checkpoint hang等待log file switch(checkpoint incomplete) 11.2.0.4 on Solaris OS 5.11
Troubleshooting log file switch (checkpoint incomplete) event

但是这里还是建议推荐阅读一下TanelPoder的Log file switch (checkpoint incomplete) wait events and LGWR waiting for checkpoint progress ， 几年前就已经拜读过，现在回头看思路很值得再次分享。

分析思路：
1， 如AWR, ASH, 或tanelpoder的脚本snapper.sql, ashtop.sql 确认top event

2， 如果是正在进行时 可以使用snapper.sql查看lgwr /ckpt的stat和top event ， wait等信息如@snapper all 30 1 lgwr(LGWR/LGnn for 12c+)，也可以暂存ash 或session信息到临时表

3， 根据#2的event 查看进程活跃时间还是空闲等待,如等其它进程调用唤醒(rdbms ipc message),通常应该是后台进程on cpu或IO类工作瓶颈，但如果不是？

4,  查看全局的等待链路，可以做hanganalyze、SSD，或进程的errorstack,procestate,short_stack dump， 也可以查询v$waitchains 或TP的脚本ash/ash_wait_chains.sql ，如 @ash/ash_wait_chains program2||event2 1=1 sysdate-1/24/12 sysdate

5, 关注最后的blocker进程和wait event， 像TP案例中ckpt等待数据文件类event direct path write，而不是 control file xx reads/writes。 注意这里的blocker并不一定是最终的blocker。

6， 要关注统计信息的次数和单次，如snapper.sql中的“waits/sec”列, 如果LGWR高频次的做control file sequential read但每次又很快，或CKPT频繁的direct path write 但也很快，那就有可能出现rdbms ipc message占用较多时间，并不是后台进程不忙，而是尝试后又自动进入了sleep。

7, 这时要思考一下如果top event是Log file switch (checkpoint incomplete)的流程背后的原理是current logfile写”满“，准备重用下一个online redo时,检查DBWR/checkpoint的进度时，发现并非所有下一个redo（将被覆盖）中受重做保护的direty buffers都已写入磁盘,因此，为了保证数据的持久性，LGWR 必须等待switch 直到DBWR完全把相关direty buffers写入磁盘，这个过程就是为什么LGWR统计信息中大量的control file sequential read，因为它在确认chkpoint进度 。 所以这个等待事件实际不是LGWR的瓶颈，而是DBWR。

8, 而案例中的(JDBC Thin Client) log file switch (checkpoint incomplete) -> (LGWR) enq: CF - contention -> (CKPT) direct path write 可以使用snpper.sql 查看ckpt在做什么，关注STATISTIC和NUM_WAITS, WAITS/SEC,EVENT. 通常CKPT是control file parallel write 等待但这里是direct path write写，有可能是在写datafile header, CKPT需要更新datafile header的checkpoint进度，如每3秒一次增量检查点,在log switch时ckpt一样要更新datafile header. 可以查看p1 p2值确认file#和block#, 这里历史可以使用ashtop.sql ，进行时可以使用snapper.sql ash=p1,p2. 最终也是ckpt因为I/O慢问题更新文件头慢，产生的堵塞。

9， 这时可以检查DBWR进程如使用snapper.sql 注意统计信息和wait，关注每秒写次和平均每次等待时间physical write total IO requests、physical write total bytes、db file parallel write 、AVERAGES，而我一般会从v$sysmetric取io信息

-- file: iops.sql
-- author: weejar.zhang (www.anbob.com)
-- 

col "Time+Delta" for a20
col "Metric" for a80

 select to_char(min(begin_time),'hh24:mi:ss')||' /'||round(avg(intsize_csec/100),0)||'s' "Time+Delta",
       metric_name||' - '||metric_unit "Metric", 
       sum(value_inst1) inst1, sum(value_inst2) inst2
 from
  ( select begin_time,intsize_csec,metric_name,metric_unit,metric_id,group_id,
       case inst_id when 1 then round(value,1) end value_inst1,
       case inst_id when 2 then round(value,1) end value_inst2
  from gv$sysmetric
  where metric_name in ('I/O Megabytes per Second',
'I/O Requests per Second','Average Synchronous Single-Block Read Latency')
  )
 group by metric_id,group_id,metric_name,metric_unit
 order by metric_name;  
 

10， 如果此时可以登录操作系统，可以使用iostat等OS层查看IO性能，比如没有开启异步IO， RAID坏盘，硬件瓶颈，有其它高IO操作如备份，OS配置设备队列深度不足等。

11,  另外osw的ps 检查进程是否是“D” “R” “S”状态，有call stack调用函数在linux有可能是semtimedop，LGWR 调用了 3 秒超时的 semtimedop 系统调用，对应DB的’rdbms ipc message’，但是等待事件“rdbms ipc message”并不是与 semtimedop 系统调用关联的唯一等待事件。有许多地方使用了 semtimedop 调用。

12,  使用OS 跟踪进程调用如

truss -d -E -p xxxxpid
strace -ttT  -p xxxxpid

结论

总之当出现blocker session是后台进程ckpt或lgwr时，记的检查DBWR繁忙程度， LGWR性能问题可能会导致实例或库级挂起，所以总时建议REDO放在更快的IO设备上。 往往因为I/O子系统性能问题，在oracle的后台进程LGWR\CKPT\DBWR复杂的关系上，显示top event可能是不同的症状。要具体分析，而不是看到Log file switch (checkpoint incomplete)就简单的增加redo log组。

References

Log file switch (checkpoint incomplete) wait events and LGWR waiting for checkpoint progress

打赏

微信扫一扫，打赏作者吧～