本文转自微信公众号《DBA的杂想》,作者潇湘隐士。转载本文请联系DBA杂念公众号。本文分享如何使用Zabbix和DPA工具(SolarWinds的DatabasePerformanceAnalyzer)分析定位SQLServer的tempdb数据库突然变大的问题。从个人经验来看,没有完美的监控工具。所谓尺长寸短。监控解决方案不应完全依赖一种工具。最好将多种监控工具搭配组合,取长补短。多方位、多层次的监控。如下图,Zabbix监控已经发出告警,磁盘空间告警和数据库无法分配新页面告警,如下图G::Diskspaceislow(used>90%)SQLInstanceMSSQLSERVER:Couldnotallocateanewpage如下图所示,可以看到G盘(这个tempdb的数据文件单独存放在磁盘上),数据文件在短短一个小时内增加了100多G。注:其实是2:55左右开始,4:00附近结束,主要集中在3:00-4:00这个时间段,所以下面我们主要分析这个时间段的数据。当Zabbix发出告警的时候,DPA其实也发出了告警,只是提示这段时间性能严重下降,等待事件的累积时间增加,指示灯由绿变红。但那时,我正在处理另一个问题。没有注意到报警信息,错过了最好的机会。当我发现问题时,我无法捕获到问题SQL,但是DPA工具捕获并捕获了相关的SQL和一些指标数据。首先我们分析这个时间段的各项指标的数据,做下钻分析,发现这个时间段的磁盘读写延迟非常高。如下截图所示,我们添加TotalI/OWaitTime等分析指标,如下图,默认只显示部分指标数据,如果需要观察其他一些指标数据,需要切换.如下图所示,总I/O等待时间也高得离谱。其实通过对比和同比分析,我们会发现在正常情况下,数据库的读写延迟基本都在10毫秒以下。如下图其中一张截图所示:按时间切片,我们观察到在3:00到4:00之间,以下两条SQL语句(SQLHash值为5444075766和3439056218的SQL语句)等待时间最多,如下截图所示:经过下钻分析,我们排除了Hash值为5444075766的SQL,重点分析了SQLHash值为3439056218的SQL语句。如下截图所示,我们发现这条SQL语句有大量的等待事件(如下图),从这些等待事件分析,主要是Memory/CPU等待事件(后面的分析会让你知道为什么Memory/CPU等待事件占多数)和PREEMPTIVE_OS_FILEOPS等待事件,根据经验判断,估计这条SQL很有可能是罪魁祸首,因为大量的PREEMPTIVE等待事件,并且PREEMPTIVE_OS_FILEOPS等待非常高。一般有大量的PREEMPTIVE_OS_FILEOPS等待事件,很有可能会发生大量的IO操作。这里,很有可能是tempdb空间被分配占用了。当然这不是绝对的。不能推断为因果关系。PREEMPTIVE_OS_GETDISKFREESPACEPREEMPTIVE_OS_FILEOPSPREEMPTIVE_OS_WRITEFILEGATHERMemory/CPUPAGEIOLATCH_UPPREEMPTIVE_OS_FILEOPS等待事件,当线程调用与文件系统相关的多个Windows函数之一时发生。这种等待类型是一般等待。然后我们从“Waits”这个维度下钻,发现这个等待事件主要是一条SQLHash值为3439056218的SQL语句,其他语句产生这个等待事件可以忽略不计。这种现象也增加了我们初步判断的正确性。从其他维度(Files)下钻分析,发现也是一条SQLHash值为3439056218的SQL语句,仔细分析这条SQL,发现一个表和一个视图关联了一个CROSSJOIN在SQL中,但在WHERE语句中两者之间没有关联条件。也就是说,这个SQL变成了笛卡尔积。另外,SQL中还有排序等操作,所以这个SQL非常消耗tempdb空间。由于笛卡尔积,内存/CPU等待是一个很大的现象。至此,分析结束。正向分析和反向确认这条SQL确实是tempdb暴增的原因。
