ITPub博客

首页 > 数据库 > SQL Server > [SQL Server] 案例分享 - 2016新年第一个case - AlwaysOn

[SQL Server] 案例分享 - 2016新年第一个case - AlwaysOn

原创 SQL Server 作者:亨利浩然王 时间:2016-01-22 15:37:52 0 删除 编辑
            大家好,自我介绍下,我叫亨利浩然王,自2010年加入微软SQL Server专家支持团队,一直工作至今,目前是专家级支持工程师。对数据库的有着浓厚的兴趣,希望将来成为一名全面的数据库专家和数据科学家。最近发现自己做的case越来越多,要超过1000个了,总算脑子里有点干货 (我当然不会分享客户的敏感信息,这点请认识我的DBA们放心),想想是不是应该拉出来分享一下了,从此决定开始写blog,不为能够有多大影响力,但求给自己留点笔记以后能够回忆一下那些心酸感和成就感。

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

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

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

    

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

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

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

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

 4.然后发现CPU1%上升到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内部具有很大的性能瓶颈:

 对于三个采样点:

 问题未发生:213022

 问题发生时间点:214143

 问题发生期间:214523

 对于等待类型进行比对:

 

 

21:30:22

21:41:43

 

21:45:23

 

WorkersCreated

805

6806

 

6804

 

maxWorkers

6528

6528

 

6528

 

根据等待次数排名

 

 

 

 

 

HADR_WORK_QUEUE

2038070077

2038153087

0.00407297084%

2038154657

0.00415000450%

HADR_LOGCAPTURE_WAIT

655556546

655639165

0.01260287926%

655639294

0.01262255720%

PAGELATCH_EX

367064300

367106386

0.01146556611%

367106653

0.01153830541%

IO_COMPLETION

138721134

138722229

0.00078935341%

138722229

0.00078935341%

LOGPOOL_CONSUMERSET

133568768

133569315

0.00040952687%

133569315

0.00040952687%

HADR_COMPRESSED_CACHE_SYNC

64675714

64680692

0.00769686130%

64680692

0.00769686130%

SLEEP_BPOOL_FLUSH

52987308

52987628

0.00060391821%

52987628

0.00060391821%

HADR_CLUSAPI_CALL

37760522

37763560

0.00804543963%

37764192

0.00971914530%

ASYNC_NETWORK_IO

36506113

36509910

0.01040099777%

36511250

0.01407161590%

HADR_TIMER_TASK

18374122

18375486

0.00742348396%

18375755

0.00888749950%

根据等待累计时间排名

 

 

 

 

 

ADR_WORK_QUEUE

2038070077

2038153087

0.00407297084%

2038154657

0.00415000450%

CLR_AUTO_EVENT

1004061732

1004061732

0.00000000000%

1004061732

0.00000000000%

HADR_FILESTREAM_IOMGR_IOCOMPLETION

17040968

17042257

0.00756412429%

17042589

0.00951237042%

HADR_CLUSAPI_CALL

37760522

37763560

0.00804543963%

37764192

0.00971914530%

HADR_TIMER_TASK

18374122

18375486

0.00742348396%

18375755

0.00888749950%

HADR_LOGCAPTURE_WAIT

655556546

655639165

0.01260287926%

655639294

0.01262255720%

ASYNC_IO_COMPLETION

117981

117988

0.00593315873%

117988

0.00593315873%

LOGPOOL_CONSUMERSET

133568768

133569315

0.00040952687%

133569315

0.00040952687%

LCK_M_X

3814846

3814901

0.00144173579%

3814901

0.00144173579%

PAGELATCH_EX

367064300

367106386

0.01146556611%

367106653

0.01153830541%



  分析结果:

 

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

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

    其中我们发现,HADR_LOGCAPTURE_WAITPAGELATCH_EX的差值比例最高:

    PAGELATCH_EX用于INSERTphysical page write

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

    从这两个症状来看,这应该是由于存在大量的INSERT和大量的COMMIT导致。此时我们在214143.xml214523.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,而这个PAGEphysical 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的骤增。

来自 “ ITPUB博客 ” ,链接:http://blog.itpub.net/30654904/viewspace-1980802/,如需转载,请注明出处,否则将追究法律责任。

上一篇: 没有了~
下一篇: 没有了~
请登录后发表评论 登录
全部评论

注册时间:2015-12-23

  • 博文量
    1
  • 访问量
    1855