近期总有开发同事过来抱怨说有写执行超时,但是查看相关语句又没有任何问题,统计正常,执行计划合理,IO压力较低,锁也正常,正常5ms可以结束的SQL竟然超时,不可思议,但由于超时的时间和频率不固定,我们很难捕捉到超时的时间点上服务器的状态,肖磊同志明锐地发现该数据库日志日志已暴涨至200+GB,于是慢慢折腾路开始。。。
--===========================================================
首先出场的是肖桑,我在旁围观,当我们发现日志暴涨这么大的时候,第一时间检查日志的使用情况
首先查看日志的大小和使用情况
DBCC SQLPERF(LOGSPACE)
发现日志文件超过200GB,日志使用率为99%,也就是说大部分是活动日志
肖桑作为DBR,自然优先考虑
DBCC LOGINFO
DBCC LOGINFO显示数据库日志文件有1.6W,几乎全部处于活跃状态(status=2)(上图只是示例)
不知道肖桑有没有运行查看过日志等待状态,反正我当时没查
--查看日志等待状态
SELECT DB.name,
DB.log_reuse_wait_desc
FROM SYS.databases DB
由于我们经常遇到镜像阻塞复制或者镜像问题导致日志增大的情况,而问题数据库恰好配置为镜像,显示状态为正在同步,SO,我们做了一个艰难的决定--取消镜像
这应该算一个轻率的决定,正常情况即使确定是镜像问题,我们仍需要确定什么导致镜像出现问题(如何检查请参考http://www.cnblogs.com/TeyGao/p/3521677.html)以及寻找最佳解决办法,或许是由于重做镜像太过简单,我们就轻易地选择了移除镜像。
镜像移除后,我们查看复制情况
--=================================================
--为每个发布数据库返回有关滞后时间、吞吐量和事务计数的复制统计信息。
--此存储过程在发布服务器的任何数据库中执行。
--http://msdn.microsoft.com/ZH-CN/library/ms190486.aspx
EXEC SP_REPLCOUNTERS
结果我们惊奇地发现:
日志中等待传送到分发数据库的事务数(Replicated
transactions):12000W+
平均每秒传送到分发数据库的事务数(Replication rate trans/sec):
7000+
我们做了一个简单的运算:SELECT 120000000.0/7000/60/60=5,考虑Replication
rate
trans/sec 的值上下波动,我们将预估时间定位4到6个小时,这个时间还在我们接受范围内,于是乎,我们选择了等待。。。
随着时间的飞逝(当年常用的可是白马过隙),Replication rate
trans/sec的值逐渐从7000+减低到4000+再到700+然后到400+,我们的预估时间变成2-4天,很恐怖的一个数字啊!
由于我们之前已经定位到vlf为数量过多,而我们潜在认为这既是影响复制的问题,所以我们没有做过多的分析便坐等复制正常,直到预估时间超过我们接受范围,此时时间距离问题发现已经过去一天多。
由于复制恢复时间超出我们预期,而且订阅对整个业务的重要性很低,可以先移除再重做,为不影响业务,我们选择移除订阅,为谨慎起见,我们没有直接删除订阅,而是选择修改订阅的存储过程,我们认为注释掉存储过程中的代码,也可以达到移除订阅类似的目的,避免订阅运行复制命令所产生的消耗,于是我们发动同事一起修改相关的付复制存储过程。
当我们费了九牛二虎之力把存储过程修改完以后,发现没有任何帮助(好悲催的赶脚)
本着生命在于折腾的精神,我开始分析传送事务越来越慢的原因,优先是检查磁盘,由于发布分发和订阅使用的都是IO卡,虽然在订阅上能捕获到一些写日志等待,但是还在接受范围内,于是我开始检查是否因为大事务导致复制问题。
--===============================================================
--在分发库上查找大事务
USE distribution
GO
SELECT xact_seqno, COUNT(*) AS [COUNT]
INTO #MSrepl_commands FROM dbo.MSrepl_commands
GROUP BY xact_seqno
HAVING COUNT(*)>100
SELECT t.xact_seqno,t.entry_time,c.[count]
FROM MSrepl_Transactions t INNER JOIN
#MSrepl_commands c ON t.xact_seqno=c.xact_seqno
ORDER BY c.count DESC,t.entry_time
天佑我大中华,我顺利抵捕获到一个包含120w命令的大事务(另外一个发布库上的发布,但是与问题发布库使用相同的分发库和订阅库),于是乎,全世界的目光集中在这个大事务上,各种炮火对准,在确定相关影响后,我们快刀斩乱码,直接将那个复制干掉了。
我们悲哀地发现,以上操作都对Replication rate
trans/sec没有任何影响,就好比北京到西藏的车流很慢,我们就把西藏到北京北京周边的路修成十车道的高速路,结果悲催发现车都堵在三环路上一样。
问题还在发布库上,我们要解决日志过大问题,要么等复制相关事务从日志被读取到分发库,要么删除复制,前者太慢不可取,只能选择删除复制,又是一个手起刀落,复制被干掉了。。。
正准备高唱“解放区的天是蓝蓝的天”的时候,心急的同事已经忙着备份日志收缩数据库了,结果悲催地发现,备份收缩无效,使用EXEC
SP_REPLCOUNTERS依然发现还有大量等待传送的事务已经慢的可怜的传说速度。。。
一定是我们打开方式不对,一定是的。。。
查看日志等待状态,小伙伴们惊奇发现,日志等待状态依然是复制,这是为什么呢?
经过仔细分析,CDC成为焦点,有业务需要依据CDC的变更记录来同步数据到ORACLE数据库,ORACLE的同事很傲娇地告诉我们,他们程序运行正常,没有问题,数据已同步。。。
当我们差点要忽略CDC的时候,作死的我还是逼着同事检查了一遍,因为复制和CDC是共用一个logreader,既然复制延迟了好几天,没道理CDC正常同步啊!
果不其然,CDC大有问题,大概了解的结果是有个应用程序会读取CDC相关的数据到ORACLE数据库,其中一个表出了问题,导致程序没有正常运行,然后就阻塞了CDC,EXEC
SP_REPLCOUNTERS显示的就是CDC的相关信息,只是被打上了复制的旗号,于是乎CSC成了挡在我们前面的绊脚石,带着佛挡杀佛人挡杀人的气势,反正我们相继灭杀了“镜像”和“复制”这两大令日志暴涨的罪恶之手,也不在乎在多灭杀一个CDC,果断再次手起刀落,整个数据库级别禁用CDC.
终于,世界清静了,日志文件的使用率也有原来的99%降低到1%,在经过几次日志备份和收缩,日志文件又恢复到正常大小,正义战胜了邪恶,七个小矮人和白雪公主又过上了幸福美满的生活,世界和平是如此的美好。。。
--========================================================
在整个处理过程中,我们急于求成到心理导致出现了很多问题,由于想着尽快解决问题,以及一定的自负心理(各位同事不要打我),让我们将没有经过太多的理论分析操作直接在生产服务器上运行,尽管我们在操作前已经评估这些操作带来的影响,却没有仔细评估这些操作是否能带来我们期望的结果,因此导致我们做了很多的无用功和浪费了很多宝贵时间,所幸所有影响都在可控和可接受范围内
PS:以上总结值得很多DBA同仁的引以为戒
--=======================================================
夜深了,你看妹子都趴着想睡觉了