杂谈--一次”失败“问题处理过程

近期总有开发同事过来抱怨说有写执行超时，但是查看相关语句又没有任何问题，统计正常，执行计划合理，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同仁的引以为戒

--=======================================================

 夜深了，你看妹子都趴着想睡觉了