2016新年钟声敲响之际，也许大家都在看芒果台，荔枝台，番茄台的跨年晚会，或者带着心上人跑到外面去看烟火，本来我也是想看个电影的，结果，被某著名电商的DBA拉住一起解决了一个SQL Server AlwaysOn 不可用的问题。某著名电商？设想当下有哪些中国互联网再用SQL Server，我想我应该都接触过吧。如果还尚未打过交道的MSSQL DBA，不妨认识一下（对了，请您支持正版，J）。 

来说说这个问题吧，电商也许是需要将2015没有开具的发票要在最后关头一起开出来，结果把数据库搞得无法连接了，无奈之下，之后通过AlwaysOn进行切换。所以问题关键在于，为什么SQL Server无法连接了。然而，找到鄙人的时候，切换都已经完成了，SQL ERRORLOG和Windows Event Log一切正常，没有异常的ERROR 或warning。这下怎么找原因呢？下面就给大家介绍一个在AlwaysOn中比较有用的日志，叫做xevent，这个日志是默认就会记录的，因为他会调用SQL Server 2012 Cluster起开始使用的IsAlive check的Sp_server_diagnostics， 他会返回一些等待类型和性能相关的阻塞信息，通过这些，我们直接找到了问题的根源。

在SQL Server ERRORLOG所在的相同目录下，可以看到类似于一下.XEL的XEVENT 文件，

使用Manage Studio打开，可以看到类似于一下的结果 

 1.问题发生时，客户端连接失败的错误为preLogin Timeout: 其中初始化部分占7.031s，handshake部门占8.015s。根据我多年经验，这通常是由于SQL Server或者整个操作系统来不及处理新进来的连接请求导致的15秒超时。  

 2.然而根据客户的描述，当时未发生自动切换，也就是说当时windows cluster服务并不认为SQL Server AlwaysOn死掉

 3.检查发现内存没有压力，首先排除内存问题导致的影响。

 4.然后发现CPU从1%上升到30%，Active Transaction飙升至7000+。根据我的经验，出现这种情况有两种可能： 

可能性1：有阻塞，等待类型将为LCK_XXXXX  

可能性2：有大量INSERT导致HOT PAGE，等待类型将为PAGELOCK_XXXX

 然而，从XEvent中发现了一些线索，确定这个问题发生的原因是由于我说的可能性2，也就是HOT PAGE INSERT导致。

 以下是我的详细分析：

 从XEVENT _SQLDIAG_0_130960353778960000.xel中，找到三个采样点，都确认诊断结果为Warning, 而对IO的诊断为clean

 说明当时IO压力不大，但是SQL Server内部具有很大的性能瓶颈：

 对于三个采样点：

 问题未发生：21：30：22

 问题发生时间点：21：41：43

 问题发生期间：21：45：23

 对于等待类型进行比对：

  分析结果：

1. 首先发现工作线程从805飙升至6806，而根据CPU计算的理论最大值是6528（超过理论值是合理的，因为会有系统线程，具体细节不在赘述），这已经表明说所有的工作线程耗尽，新的连接无法进来即是情理之中了。

2. 从等待类型来看，不管是根据等待次数还是根据等待的累计时间来算，因为都是从服务启动开始算起，所以排名不具备参考价值。只有差值是有必要考量的。

   其中我们发现，HADR_LOGCAPTURE_WAIT和PAGELATCH_EX的差值比例最高：

   PAGELATCH_EX用于INSERT的physical page write

   HADR_LOGCAPTURE_WAIT用于COMMIT时在本地进行日志抓取并发送到Secondary

   从这两个症状来看，这应该是由于存在大量的INSERT和大量的COMMIT导致。此时我们在214143.xml和214523.xml中发现有阻塞的样例结果（只输出前5行）

   我们发现全都是IF @@TRANCOUNT>0 COMMIT TRAN 

         <blocked-process-report monitorLoop="0"><blocked-process><process clientoption2="128058" clientoption1="671088672" lockTimeout="4294967295" currentdb="" xactid="5257386798" isolationlevel="read committed (2)" loginname=" " hostpid="0" hostname=" " clientapp=" " lastattention="1900-01-01T00:00:00.723" lastbatchcompleted="2015-12-31T21:42:34.723" lastbatchstarted="2015-12-31T21:42:34.723" trancount="1" priority="0" ecid="0" sbid="0" spid="" status="suspended" kpid="32268" schedulerid="18" waittime="1917" id=" "><executionStack><frame sqlhandle="" stmtend="58" stmtstart="38" line="1"/><!--executionStack><inputbuf> IF @@TRANCOUNT > 0 COMMIT TRAN <!--inputbuf><!--process><!--blocked-process>

         在同步模式的情况下，COMMIT TRAN要求先完成REMOTE HARDEN。

        BEGIN TRAN --- 这些都是慢慢传 

         STATEMENT1 --- 这些都是慢慢传
           …

          STATEMENT100 --- 这些都是慢慢传

          COMMIT --- 一旦发现有这句话，必须保证这句话之前的所有LOG都传到Secondary。如果之前的还没传完，要等之前先传完。

 由于大家都在COMMIT，大家都等待：HADR_LOGCAPTURE_WAIT，并且网络I/O增加了负载压力也都是顺理成章了。

 那么为什么等待PAGELATCH_EX?

 <blocked-process><process clientoption2="128056" clientoption1="671088672" lockTimeout="4294967295" currentdb="" xactid="5257318982" isolationlevel="read committed (2)" loginname=" " hostpid="0" hostname=" " clientapp="" lastattention="1900-01-01T00:00:00.127" lastbatchcompleted="2015-12-31T21:38:14.127" lastbatchstarted="2015-12-31T21:38:14.127" trancount="1" priority="0" ecid="0" sbid="0" spid="819" status="suspended" kpid="10128" schedulerid="11" waittime="804" id="process1ec5a0650c8"><executionStack><frame sqlhandle="" stmtstart="502" line="1"/><frame sqlhandle="" line="1"/><!--executionStack><inputbuf>(@P0 bigint,@P1 int,@P2 varchar(8000),@P3 varbinary(8000),@P4 smallint,@P5 varbinary(8000),@P6 varbinary(8000),@P7 varbinary(8000),@P8 varbinary(8000),@P9 varbinary(8000),@P10 smallint,@P11 varbinary(8000),@P12 varbinary(8000),@P13 datetime2) insert into table_name values( @P0, @P1, @P2, @P3, @P4, @P5, @P6, @P7, @P8, @P9, @P10, @P11, @P12, @P13 ) <!--inputbuf><!--process><!--blocked-process>

 我怀疑有自增列导致的hotpage，根据与客户确认，发现确实如此。由于自增列ID，导致所有并发的INSERT都要插入到最后一个PAGE，而这个PAGE的physical write就变成了瓶颈。这就好比很多人要上火车，结果只有最后一个门打开了，大家上火车就会慢。如果门多了，上火车就会快了。怎样可以让门的个数变多呢？其实很简单，就是不要使用自增列，您可以考虑让主键ID具有一定的含义，比如中间几位代表品类、地点、时间等等，这样大家就会插入到不同的数据页。这就是为啥你看到网购的订单都那么长了。

 附加

=========

这是一个LOCK Blocking吗？

根据上述排查，LCK_M_X的等待并没有显著升高，我们暂时排除了“可能性1”.   

综上所述： 
  问题从21:38分开始恶化，21:41分所有线程耗尽，连接问题开始失败，一直到21:52分发生切换。在此期间，“IF @@TRANCOUNT > 0 COMMIT TRAN”的大量涌入，导致了SQL Server突然需要读取/传递/Remote harden大量的日志，从而造成本地磁盘和网络IO负载，以及CPU的增加，“insert into table”的大量涌入导致了SQL Server，导致了HOT PAGE，以及PAGELATCH_X的骤增。