讨厌香草冰激精的汽车与Buffer busy wiats的故事
记得好几年前看到过一个故事,通用公司曾收到一客户的邮件,邮件中客户描述了一个非常奇怪的问题。他们家有晚饭后去吃冰激凌的习惯,如果他们买的是香草味的冰激凌,则会打不着车子,买其他口味则没有问题。
“汽车讨厌香草味冰激凌?”,这封奇怪的邮件,并没有被通用不屑一顾的弃之一边,相反通用反而派出工程师,专程到客户哪里调查问题。调查的结果大出人的意料,客户邮件中的问题,的确属实。
而后工程师连续几天,每晚同客户一起去买冰激凌,而客户的问题,的确是“重可现”的,每次买香草味冰激凌,果然打不着车子。
得到这个不靠谱的结果,通用没有找理由搪塞客户,而是让工程师继续调查。哪名工程师也够执着,在对汽车的一系列检查无果后,他转向客户买冰激凌的过程。他沉着的记下了客户买冰激凌的每个细节。然后,经过对细节的对比,他发现问题的根源有可能是时间。因为香草冰激凌最为畅销,因此商店将放在最显眼的地方,最容易找到。因此,“买香草冰激凌”这个动作所花的时间,比“买其他冰激凌”要短。这名工程从时间上着手,终于找到了通用汽车的一个漏洞。
从不着边的事情入手,怀着一份好奇心,将目观关注在细节上,就能发现不靠谱的问题,原来挺靠谱。
好,故事讲完了,下面说一个数据库的问题 。
前些时应朋友之邀,帮忙诊断一个数据库问题,10.2.0.4,单实例的,现象很普通,就是客户反应慢。以半小时为期,查了几份AWR,I/O没有问题,日志文件写I/O有点慢,但量不大。TOP5等待中,buffer busy waits排的比较靠前。于是优化了几个逻辑读比较高的SQL,客户反应慢的操作,已经有反好转。再看buffer busy waits,有所缓解,但在AWR报告中还是有点靠前。按说,到这一步工作也就结束了,按常通常的理解,如果不能使用更小的数据块、在数据块中放入更少的行,buffer busy waits也没有什么好方法可以进一步调优了。更何况,客户反应已经可以,不需要再继续下去。。但是,正像“买香草冰激凌就打不着车”一样,我相信细节、好奇心,决定成败,特别是DBA这份工作尤是。我决定再仔细查查原因。
Oracle数据库是一个庞大而复杂的软件,正是因为如此,才需要有DBA这个工种,专门维护它。这么复杂的一个软件系统,出现问题,往往都不是独立的,而是各种情况交织在一起的。如何从纷乱的信息中,找到入口点呢?我决定采取和通用工程师一样的方法,从时间上入手。仔细观察ASH视图,运气还算好,果然发现buffer busy waits有明显的、不定时的周期性。每隔一段不定长的时间,十分钟左右,就会突然高一下。
很多时候,是没有这个好运气的。去年还在阿里时,为了查一个库回滚段空间为什么不足,我足足花了两周时间,做了N种测试方案,最终才定位到问题。现在也有时间了,我会慢慢整理出来,大家可以关注 www.mythdata.com。
继续讨论今天的话题,在buffer busy waits的升高的同一时间点,还发现了Log file sync也会突增一下,但升幅没有buffer busy waits高。问题很可能会和日志文件有关联。进一步查看日志文件的切换,最后,终于定位到问题---日志切换。
每次日志切换时,buffer busy waits的等待总会突然严重一些,而后下降至正常水平。
buffer busy waits竟然和日志文件有关联,这还是第一次注意到。而且,Log file sync和日志切换的关联,比Buffer busy waits要大很多。但为什么这里却看到了相反的结果?问题的原因找到了,但更大的问题来了,这一切的原因是什么。而且,进一步观察,手动切了一个日志,发现等待Buffer busy waits的Session,都正在执行Select,没有DML。
日志切换,会导致Select等待Buffer busy waits。
和通用客户的问题一样,我也得到了一个奇怪的结论。为了测试是否在所有数据库是都是如此,我找了测试环境,测试如下:
环境:版本10.2.0.4,Redo File大小200M,OS是Solaris。
步1:打开两个测试用Session,此处SID分别是858和859,在另一会话处记录测试前数据:
set linesize 1000
col event for a30
select EVENT,TOTAL_WAITS,TOTAL_TIMEOUTS,TIME_WAITED_MICRO/100 from v$SYSTEM_EVENT where event in ('buffer busy waits','log file sync');
每次日志切换时,buffer busy waits的等待总会突然严重一些,而后下降至正常水平。
buffer busy waits竟然和日志文件有关联,这还是第一次注意到。而且,Log file sync和日志切换的关联,比Buffer busy waits要大很多。但为什么这里却看到了相反的结果?问题的原因找到了,但更大的问题来了,这一切的原因是什么。而且,进一步观察,手动切了一个日志,发现等待Buffer busy waits的Session,都正在执行Select,没有DML。
日志切换,会导致Select等待Buffer busy waits。
和通用客户的问题一样,我也得到了一个奇怪的结论。为了测试是否在所有数据库是都是如此,我找了测试环境,测试如下:
环境:版本10.2.0.4,Redo File大小200M,OS是Solaris。
步1:打开两个测试用Session,此处SID分别是858和859,在另一会话处记录测试前数据:
set linesize 1000
col event for a30
select EVENT,TOTAL_WAITS,TOTAL_TIMEOUTS,TIME_WAITED_MICRO/100 from v$SYSTEM_EVENT where event in ('buffer busy waits','log file sync');
EVENT TOTAL_WAITS TOTAL_TIMEOUTS TIME_WAITED_MICRO/100
------------------- ----------- -------------- ---------------------
buffer busy waits 479 8 131918.28
log file sync 11 2 39382.83
------------------- ----------- -------------- ---------------------
buffer busy waits 479 8 131918.28
log file sync 11 2 39382.83
步2:
(1)、先在859会话开始跑如下程序块:
declare
j number;
begin
for i in 1..30000 loop
select count(*) into j from a1;
end loop;
end;
/
这其中,表A1的所有数据,只占1块数据块,全扫描表1,只需要11个逻辑读。
(1)、先在859会话开始跑如下程序块:
declare
j number;
begin
for i in 1..30000 loop
select count(*) into j from a1;
end loop;
end;
/
这其中,表A1的所有数据,只占1块数据块,全扫描表1,只需要11个逻辑读。
(2)、马上在858号会话开始执行如下包含DML的程序块:
declare
j number:=0;
begin
for i in 1..30000 loop
update a1 set id=id+0 where id<=10;
if j >= 100 then
commit;
j:=0;
end if;
j:=j+1;
end loop;
commit;
end;
/
反反复复的更新A1表,每更新100次,提交一次。
declare
j number:=0;
begin
for i in 1..30000 loop
update a1 set id=id+0 where id<=10;
if j >= 100 then
commit;
j:=0;
end if;
j:=j+1;
end loop;
commit;
end;
/
反反复复的更新A1表,每更新100次,提交一次。
步3:在步2中的两段程序执行完后,再次用步1中的SQL统计buffer busy waits和Log file sync的等待次数和时间。减去步1时的值。同时查询V$LOG,确定是否有日志切换。
结果:我反复重复了N次如上测试,没有日志切换时,buffer busy waits通常等待少于3万次,2万9千多次和3万次之间。有日志切换时,这个值略有上升,在3万到3万零几百次之间。虽然次数差别不大,但等待时间上,差别可就大多了,没有日志切换时,等待时间在27、28秒左右,有日志切换时,则是58秒左右。
既然走到这一步,不如再测一下。日志切换会影响buffer busy waits,原因还在于日志切换时,写日志文件会有短暂的阻塞。也就是说,写日志文件的速度,会影响buffer busy waits。进一步测试一下。将日志文件的位置移到更快速的存储设备上再测,从等待次数上看,下降不是很多,但从时间上看,下降非常明显,从原来的58秒(有切换)、27秒(无切换),下降到0.6秒(有切换)、0.5秒(无切换)。下降分别100倍(有切换)、50倍(无切换)。
我分别在新、老Redo文件存储上,用dd命令测试了一下写入速度,原位置每秒200M左右,新位置每秒700M左右。写入速度增加了3至4倍,但buffer busy waits等待时间减少了至少50倍。看来,日志文件的写入性能,对buffer busy waits影响颇大啊。
结果:我反复重复了N次如上测试,没有日志切换时,buffer busy waits通常等待少于3万次,2万9千多次和3万次之间。有日志切换时,这个值略有上升,在3万到3万零几百次之间。虽然次数差别不大,但等待时间上,差别可就大多了,没有日志切换时,等待时间在27、28秒左右,有日志切换时,则是58秒左右。
既然走到这一步,不如再测一下。日志切换会影响buffer busy waits,原因还在于日志切换时,写日志文件会有短暂的阻塞。也就是说,写日志文件的速度,会影响buffer busy waits。进一步测试一下。将日志文件的位置移到更快速的存储设备上再测,从等待次数上看,下降不是很多,但从时间上看,下降非常明显,从原来的58秒(有切换)、27秒(无切换),下降到0.6秒(有切换)、0.5秒(无切换)。下降分别100倍(有切换)、50倍(无切换)。
我分别在新、老Redo文件存储上,用dd命令测试了一下写入速度,原位置每秒200M左右,新位置每秒700M左右。写入速度增加了3至4倍,但buffer busy waits等待时间减少了至少50倍。看来,日志文件的写入性能,对buffer busy waits影响颇大啊。
我将测试结果告知客户哪边的DBA,请他如果可能的话,将Redo文件放在更快的存储设备上。他果然找到一个空闲的8块盘的RAID10,将Redo文件重建在了上面,之后,buffer busy waits果然又下降很多,不但不会再出现在TOP 5中,而且几乎下降到没有。
但是,用户体验哪边,反应平平,因为SQL调优之后,性能已经可以满足他们的需要。呵呵,这是正常的。百尺竽头,更进一步的调优是很困难的,而且,很多时候用户也并不十分认可这样的调优。也只有对技术有追求的人,才会坚持下去,追求将技术做到极致。
我认为一家公司,大家各司其职。销售尽一切力量去推销,将销售做的极致;行政将服务做到极致;而技术人员,则想方设法将技术做到极致。哪么这个公司,就一定拥有无比的竞争力。就比如Google,就连厨房都可以做成精典。还有乔布斯,将东西做到极致的精神,使苹果在全球拥有众多忠实粉丝。
但是,用户体验哪边,反应平平,因为SQL调优之后,性能已经可以满足他们的需要。呵呵,这是正常的。百尺竽头,更进一步的调优是很困难的,而且,很多时候用户也并不十分认可这样的调优。也只有对技术有追求的人,才会坚持下去,追求将技术做到极致。
我认为一家公司,大家各司其职。销售尽一切力量去推销,将销售做的极致;行政将服务做到极致;而技术人员,则想方设法将技术做到极致。哪么这个公司,就一定拥有无比的竞争力。就比如Google,就连厨房都可以做成精典。还有乔布斯,将东西做到极致的精神,使苹果在全球拥有众多忠实粉丝。
这个问题还没有完,为什么在客户现场看到的,等待buffer busy waits的,都是Select?
还有,更进一层,为什么日志文件的写入性能,会这么严重的影响buffer busy waits,进而影响逻辑读的性能呢?
请继续关注。
还有,更进一层,为什么日志文件的写入性能,会这么严重的影响buffer busy waits,进而影响逻辑读的性能呢?
请继续关注。
来自 “ ITPUB博客 ” ,链接:http://blog.itpub.net/321157/viewspace-717344/,如需转载,请注明出处,否则将追究法律责任。
转载于:http://blog.itpub.net/321157/viewspace-717344/