log file sync 等待超高一例子
本站文章除注明转载外,均为本站原创: 转载自love wife love life —Roger的Oracle/MySQL/PostgreSQL数据恢复博客
本文链接地址: log file sync 等待超高一例子
这是3月份某客户的情况,原因是服务器硬件故障后进行更换之后,业务翻译偶尔出现提交缓慢的情况。我们先来看下awr的情况。
我们可以看到,该系统的load profile信息其实并不高,每秒才21个transaction。先来看看top5events:
从top 5event,我们可以发现,log file sync的avg wait非常之高,高达124ms。大家应该知道,对于绝大多数情况
下,log file sync的平均等待时间是小于5ms的,这个值有点高的离谱。
我们知道,产生log file sync等待的原因有很多。关于log file sync,tanel Poder大神写过一篇很牛的pdf,大家可以参考下。
这里我主要引用大神的图,来简单描述产生log file sync的原因可能有哪些,首先我们来看下从前端进程提交到最后得到反馈时,以及中间处理的整个流程情况:
从上图中,我们可以清楚的看到整个流程。这里可以进行简单的描述:
1、当user发起一个commit后;
2、前端进程(即Server 进程)会post一个信息给lgwr进程,告诉它,你应该去写redo buffer了。
3、当LGWR进程得到指示后,开始调用操作系统函数进行物理写,在进行物理写的这段时间内,会出现
log file parallel write等待。这里或许有人会有疑问,为什么12c之前只有一个lgwr进程,这里却是parallel
write呢?这里需要说明一下,lgwr进程在将redo buffer中的数据写出到log file文件中时,也是以batch方式
进程的(实际上,dbwN进程也是batch的模式),有相关的隐含参数控制。
4、当LGWR完成wrtie操作之后,LGWR进程会返回一个信息给前端进程(Server进程),告诉它,我已经写完了,
你可以完成提交了。
5. user 完成commit操作。
这里补充一下,这是由于Oracle 日志写优先的原则,假设在commit之前redo buffer的相关entry信息不立即写到redo
log file中,那么如果数据库出现crash,那么这是会丢数据的。
从上面的流程图,我们其实也可以看到,log file sync和log file parallel write可以说是相互关联的。换句话讲,如果log file parallel write的时间很长,那么必然导致log file sync等待时间拉长。
我们假设log file parallel write 等待很高,那么着可能通常是物理磁盘IO的问题,如下:
我们从上图可以发行,如果LGWR进程在完成IO操作的过程中时间过长,那么将导致log file parallel write等待升高。
实际上,在整个当用户发出commit到完成commit的过程中,涉及到很多环节,并不是仅仅只有物理IO会影响log file sync/log file parallel write。还有CPU也会影响Log file sync和log file parallel write。我们再来看个图:
我们可以看到,上述流程中的4个环节都涉及到CPU的调度,如果在整个事务commit的过程中,系统CPU出现极度紧张,那么这可能会导致LGWR进程无法获得CPU,会进行排队等待,显然,这势必将导致log file sync或log file parallel write等待
的升高。
备注:Oracle中还可以通过隐含参数_high_priority_processes 来控制进程获取CPU的优先级。在一个cpu相对缺乏的系统中,可以通过设置该参数来进行缓解。
最后我们再回到这个案例中来,客户这里的环境,我们是可以排除CPU问题。那么最大的嫌疑可能就是存储本身的问题,导致IO很慢,然而,实际上这也是可以排除的,大家其实应该注意到前面的Top 5 event了,log file parallel write的平均等待
时间并不高,如果是存储IO问题,那么这个event的平均等待时间应该是比较高才对。
我们可以看到log file sync和log file parallel write的waits都是差不多的。但是log file parallel write的avg wait time仅仅只有4ms,这是一个正常的值。也就是说可以我们排除存储IO问题。
那么问题是什么呢 ?我们利用Oracle MOS提供的脚本来查询下log file sync和log file parallel write等待的分布情况:
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 |
INST_ID EVENT WAIT_TIME_MILLI WAIT_COUNT ---------- ---------------------------------------- --------------- ---------- 1 log file sync 1 259306 1 log file sync 2 2948999 1 log file sync 4 1865918 1 log file sync 8 173699 1 log file sync 16 43194 1 log file sync 32 6095 1 log file sync 64 1717 1 log file sync 128 2458 1 log file sync 256 5180 1 log file sync 512 9140 1 log file sync 1024 558347 1 log file parallel write 1 5262 1 log file parallel write 2 4502377 1 log file parallel write 4 1319211 1 log file parallel write 8 46055 1 log file parallel write 16 23694 1 log file parallel write 32 3149 1 log file parallel write 64 283 1 log file parallel write 128 267 1 log file parallel write 256 157 1 log file parallel write 512 73 1 log file parallel write 1024 42 1 log file parallel write 2048 39 1 log file parallel write 4096 103 1 log file parallel write 8192 21 1 log file parallel write 16384 22 1 log file parallel write 32768 190 1 log file parallel write 65536 1 |
大家可以简单的计算一下,其实log file sync和log file parallel write 等待事件,几乎99%左右的平均等待时间都是
小于等于4ms的,这是属于正常的情况;然而有少数的情况其等待时间是很长的,例如log file sync最高的单次等待
时间高达1秒,由于偶尔的等待很高,因此将整个log file sync的平均等待时间拉高了。
到最后,问题就比较清楚了,我认为这是由于主机和存储之间的链路可能出现异常或不稳定导致。临时的解决方法
将redo logfile 挪到本地磁盘,解决了该问题。
后记:经客户后面确认,确实是存储光纤线接口松了。 哈哈
8 Responses to “log file sync 等待超高一例子”
果然大牛啊! 能否提供下MOS的脚本文档号?
脚本能提供下吗,谢谢!
脚本应该是通过查询gV$EVENT_HISTOGRAM得到的内容
这几个图不错,O(∩_∩)O哈!,收藏了
[…] 那么问题是什么呢 ?我们利用Oracle MOS提供的脚本来查询下log file sync和log file parallel write等待的分布情况: ? […]
谢谢Roger分享,纠正了我以前一直以为的log file sync一定和IO相关的错误观点。另外,查了一下,MOS的文章号是1064487.1
哈哈,期待大家多多分享
运气不错,客户认了哈
Leave a Reply
You must be logged in to post a comment.