合 SQL Server排查异常慢SQL及性能
Tags： MSSQLSQL Server性能慢SQL性能排查慢查询异常SQL
简介
作为数据库管理员，很多时候会遇到线上堵塞的情况，或者是客户与相关部门同事反馈系统出现等待。虽然整个架构各环节都有可能影响着业务系统的性能，但是他们往往首先把“矛头”指向数据库。那么，这时候你该如何处理呢？
即使很多时候不是数据库的问题，但是在数据库端进行排查，也可以间接发现引起系统慢的原因。比如，网络带宽、磁盘、连接、代码、SQL等各种问题。在问题发生的时刻，线上排查是最容易发现问题根源的。而有的时候，我们可能还没发现问题根源，就用了其他手段先解决了当下的问题，待后续再进行问题溯源。
作为数据库的管理员，我们应该知道如何在线上排查问题，或者在事件过后确认问题，以防止此类事件再次发生。在SQL Server中，大部分的问题都反映在连接和执行的SQL上，如果你知道如何查找这些连接和SQL，你就可以从中判断系统问题了。
线上堵塞如何排查？
- 通过监控系统或告警信息确认数据库系统是否正常运行；
- 通过监控系统或告警信息确认CPU、Mem、IO、带宽是否异常；
- 通过监控系统确认数据库实例的连接数、堵塞/死锁情况、长事务、QPS/TPS、命中率等是否异常；
- 通过数据库系统记录的历史运行数据，确认是否异常；
- 通过数据库错误日志及Windows系统日志是否报错；
以上的排查问题在事发前、中、后的基本处理方案。但是，一个平时稳定运行的系统，通常很少出现异常。除非你对操作系统或数据库实例进行了相关补丁和更改参数。如果仅仅是日常的产品升级、SQL脚本升级，在数据库中几乎都可以通过连接发现其中的问题。
首先了解几个系统DMV，用于查看当前的连接信息。
- sys.dm_exec_connections 记录当前连接到实例的连接协议、网络信息等。
- sys.dm_exec_sessions 记录当前连接到实例的客户端信息、配置信息、操作统计信息等。
- sys.dm_exec_requests 记录当前正在请求的信息，如执行参数、等待信息、资源消耗信息等。
- sys.sysprocesses 记录当前活动连接（包括正在请求）的客户端信息、等待信息、资源消耗信息等。
以上几个DMV，我们可以从中获取到以下的关键信息：
| 关键信息 | dm_exec_connections | dm_exec_sessions | dm_exec_requests | sysprocesses |
|---|---|---|---|---|
| sql_handle | 1 | 0 | 1 | 1 |
| plan_handle | 0 | 0 | 1 | 0 |
| Blocked Session | 0 | 0 | 1 | 1 |
| Status | 0 | 1 | 1 | 1 |
| WaittypeWait Resources | 0 | 0 | 1 | 1 |
| CPU/IO/Men/Rows | 1 | 1 | 1 | 1 |
| Running Time | 1 | 1 | 1 | 1 |
| Client info | 0 | 1 | 0 | 1 |
其中dm_exec_requests与sysprocesses可以确认当前系统正在执行中的连接、该连接处于什么状态、是否被堵塞、堵塞类型及等待资源、执行了多长时间、消耗的资源如何、客户端信息等。这些都是非常重要关键信息，在表中都有相应的字段对应。此外，还可以通过sql_handle与sys.dm_exec_sql_text()查看最近执行的SQL语句。
首先在线查看当前数据库连接的运行情况（如通过sysprocesses查看），重点关注正在运行的连接（kpid>0）、堵塞连接（blocked>0）、未提交的连接（open_tran>0）
1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 30 31 32 33 34 35 36 37 38 39 40 41 42 43 44 45 46 47 48 49 50 51 52 53 54 55 56 57 58 59 60 61 62 63 64 65 66 67 68 69 70 71 72 73 74 75 76 77 78 79 80 81 82 83 84 | -- 当前正在执行的SQL(包括等待的SQL、当前正在堵塞与被堵塞SQL) SELECT spid, blocked blocking, P.dbid, db_name(P.dbid) dbname, (waittime/1000) waittime, lastwaittype, waitresource, open_tran, status, cpu, physical_io, memusage, login_time, last_batch, hostname, [program_name], hostprocess, cmd, nt_domain, nt_username, net_address, net_library, loginame, sql_handle, TEXT , 'kill '+cast(spid as varchar) kill1 FROM master.dbo.sysprocesses P CROSS apply sys.dm_exec_sql_text ( P.sql_handle ) s WHERE P.spid <>@@spid and (P.status !='sleeping' or (P.status='sleeping' and P.spid IN(select blocked from master.dbo.sysprocesses nb where blocked > 0 ))) order by waittime desc GO SELECT req.session_id , req.total_elapsed_time AS duration_ms , req.cpu_time AS cpu_time_ms , req.total_elapsed_time - req.cpu_time AS wait_time , req.logical_reads , SUBSTRING (REPLACE (REPLACE (SUBSTRING (ST.text, (req.statement_start_offset/2) + 1, ((CASE statement_end_offset WHEN -1 THEN DATALENGTH(ST.text) ELSE req.statement_end_offset END - req.statement_start_offset)/2) + 1) , CHAR(10), ' '), CHAR(13), ' '), 1, 512) AS statement_text FROM sys.dm_exec_requests AS req CROSS APPLY sys.dm_exec_sql_text(req.sql_handle) AS ST ORDER BY total_elapsed_time DESC; -- 当前正在执行的SQL select session_id,db_name(dbid) as dbname,transaction_id,wait_type,last_wait_type,wait_resource ,start_time,status,command,estimated_completion_time,cpu_time,logical_reads ,text,open_transaction_count,open_resultset_count,percent_complete from sys.dm_exec_requests r cross apply sys.dm_exec_sql_text(r.sql_handle)s where session_id>50 and session_id<>@@spid go select spid,blocked,db_name(p.dbid),waittime,lastwaittype,waitresource,open_tran,status ,p.dbid,cpu,physical_io,memusage,login_time,last_batch,hostname,[program_name] ,hostprocess,cmd,nt_domain,nt_username,net_address,net_library,loginame,sql_handle,text from master.dbo.sysprocesses p cross apply sys.dm_exec_sql_text(p.sql_handle) s where kpid >0 and p.spid>50 and p.spid<>@@spid go -- 当前正在堵塞与被堵塞SQL select spid,blocked,waittime,lastwaittype,waitresource,open_tran,status ,p.dbid,cpu,physical_io,memusage,login_time,last_batch,hostname,[program_name] ,hostprocess,cmd,nt_domain,nt_username,net_address,net_library,loginame,sql_handle,text from master.dbo.sysprocesses p cross apply sys.dm_exec_sql_text(p.sql_handle) s where blocked >0 or spid in(select sp.blocked from master.dbo.sysprocesses sp where sp.blocked>0) go -- 是否有未提交事务 Select spid,blocked,waittime,waittype,waitresource,db_name(p.dbid) dbname,cpu,physical_io,memusage,open_tran ,status,login_time,last_batch,hostname,program_name,hostprocess,loginame,cmd,text from master.dbo.sysprocesses p cross apply sys.dm_exec_sql_text(p.sql_handle) s where open_tran <> 0 --and last_batch < dateadd(minute,-15,getdate()) go -- 历史 select top 10 * from sys.dm_os_wait_stats d where d.wait_time_ms > 0 order by d.wait_time_ms desc; |
按这几类确认当前连接数是否过多，或在确认线程情况sys.dm_os_threads是否充足。
重点关注status与waittype，可以确定当前连接正在等待什么资源，如网络IO等待ASYNC_NETWORK_IO（说明网络堵塞、或者客户端读取大量数据）、线程等待CXPACKET（说明并发执行SQL）、日志写等待WRITELOG（说明大量数据更改、或者磁盘问题）、线程调度等待SOS_SCHEDULER_YIELD（CPU或线程不足、或是没有索引、任务耗时长等）……waittype类型几百个，从该类型的等待情况，可以间接判断问题发生在哪里。（更多等待事件说明请参考：https://www.sqlskills.com/help/waits/ ）
有哪些异常SQL，如何确认？
在线SQL（正在运行的SQL、堵塞SQL、未提交的SQL）
慢SQL
堵塞SQL
死锁SQL
在线SQL/在线连接：通过上文中的SQL脚本，我们可以查询到正在运行的SQL、堵塞SQL、未提交的SQL，但是只能查询到系统当前时刻正在连接或运行的SQL。通过当前连接情况判断此刻堵塞的原因。线上的SQL如果出现大量堵塞，评估影响情况后，可以把堵塞的SQL连接进行kill回滚。
慢SQL：慢SQL需要跟踪收集才能发现，不可能每次都在线查询SQL去判断，且在线查询不能准确得到慢SQL的资源开销情况。通过扩展事件rpc_completed与sql_batch_completed来记录SQL的运行结果，注意添加筛选条件duration（单位为微妙）。此时慢SQL跟踪的是执行结束的SQL，只有执行结束，才能确认具体开销情况。
堵塞SQL：堵塞SQL也需要跟踪收集才能被记录。通过扩展事件blocked_process_report记录堵塞的事件。记录信息为XML格式。
死锁SQL：系统自动启用的扩展事件system_health可以捕获到死锁，只不过捕获不全且会被循环覆盖。你也可以通过跟踪标志1222或者1204进行捕获，死锁信息则记录到SQL Server 错误日志中，但这并不好筛选。可以通过扩展事件xml_deadlock_report记录死锁事件。记录信息为XML格式。
事后排查方法
我们已经通过线上排查，或者通过SQL跟踪，可以找到异常的连接和异常SQL。那么，如果问题已经结束。我们还能如何确认系统的历史运行情况呢？
事后排查方法：
- 历史线程数
- 历史CPU使用率
- 历史内存使用
- 历史异常连接
- 历史IO统计
- 历史缓存SQL
- 历史等待类型
- …………
历史线程数：通过系统自动跟踪的扩展事件system_health，筛选对象为sp_server_diagnostics_component_result，解析XML文件可以查看系统近段时间内的线程数。可以判断线程是否充足。
历史CPU使用率：通过系统记录的ring buffer（dm_os_ring_buffers），筛选类型为RING_BUFFER_SCHEDULER_MONITOR，可以找到近段时间内CPU的使用率。如果你没有对数据库服务器进行监控，这是不错的方法。ring buffer 维护大约 1000 条记录，超过则循环覆盖。
历史内存使用：同样的方法，可以通过系统DMV dm_os_ring_buffers 筛选类型为RING_BUFFER_RESOURCE_MONITOR 的记录。可以查看近段时间内内存的使用情况。
历史异常连接：同样的方法，可以通过系统DMV dm_os_ring_buffers 筛选类型为RING_BUFFER_CONNECTIVITY 的记录。可以查看近段时间内异常连接情况。
历史IO统计：SQLServer有一个DMV sys.dm_io_virtual_file_stats，记录着数据文件和日志文件的IO统计情况。通过该视图，可以确认哪些数据库读写与耗时最多，以针对指定数据库进行相应优化。
历史缓存SQL：对于已经执行过的SQL，我们有慢SQL与堵塞SQL跟踪，不过这是有限制性的筛选。我们还可以通过查询缓存中的编译对象，找到缓存计划中的SQL。通过4个DMV dm_exec_cached_plans、dm_exec_query_stats、dm_exec_procedure_stats、dm_exec_trigger_stats，其字段sql_handle和plan_handle与另外2个DMV sys.dm_exec_sql_text和sys.dm_exec_query_plan关联，可以查看到具体的SQL和执行计划。你可以找耗时最长、耗IO最多、执行频繁的SQL等，将它们找出来进行优化。
历史等待类型：我们确认在线连接及SQL的时候，重点关注了等待类型，等待类型确定客户端连接主要的瓶颈在哪里。系统函数sys.dm_os_wait_stats记录着实例启动以来不同类型的等待情况，从中我们可以确定数据库实例的主要瓶颈在哪里。
如果你们已经完善了这些监控，可以从监控平台或数据收集等平台来回顾分析问题发生的原因。
如何优化异常SQL
我们已经找到了这些异常SQL，该如何优化呢？
优化SQL。查找慢SQL、堵塞SQL、死锁SQL、资源开销大的SQL进行优化，如改写SQL、优化索引。
缺失索引。通过此类视图
sys.dm_db_missing_index_*发现缺失的索引，或者通过dm_exec_query_plan查看缓存执行计划中有提示缺失索引（MissingIndex=1）的执行计划，创建相关索引。。重复索引。通过视图sys.indexes与sys.index_columns找到重复索引、或者前缀字段相同的索引删除。
索引碎片。DML操作频繁，产生较多碎片，将导致表比较大，增加了磁盘IO。通过系统视图dm_db_index_physical_stats，查找碎片较多的索引，定期进行重组或重建，亦或者定期更新统计信息。必须注意的是，确保磁盘空间足够（重建索引后可有效收缩表空间）。
调整参数。实例级别的参数配置，可通过sp_configure查看和设置。比如一些影响SQL的重要参数max degree of parallelism、optimize for ad hoc workloads、max server memory (MB)等。
12345678910111213141516171819202122232425sp_configure 'show advanced options', 1;GORECONFIGURE WITH OVERRIDE;GO-- 配置最大内存为1024Msp_configure 'max server memory (MB)',1024go-- CPU数无限制sp_configure 'max degree of parallelism', 0;GO-- 超过8秒使用并行sp_configure 'cost threshold for parallelism', 8;GO-- 开启即席查询sp_configure 'optimize for ad hoc workloads',1go-- 使设置生效RECONFIGURE WITH OVERRIDE;GO
通过连接数据库系统的客户端，我们都可以从上面的排除方法确认是否是数据库的问题。稳定运行的系统若出现异常，这种情况也是比较好排查的。前提是，你一定要对数据库服务器进行监控，甚至对异常SQL的收集。否则当你遇到业务系统的问题，不希望自己去担这个锅吧。只有有理有据，别人才能信服。
数据库系统遇到的问题，第一时间可以在线查看连接情况，及时解决系统堵塞问题。如果都正常，再查看相关的日志和历史监控记录，确认资源是否充足。历史经验中，作者有几次遇到的是出口带宽的问题，导致业务系统访问卡顿。不过，只要客户端连接到了数据库，我们都可以从连接信息判断是否是网络IO的问题。
排查SQL Server上运行缓慢的查询问题
查找慢速查询
若要确定SQL Server实例存在查询性能问题，请首先按查询的执行时间 (运行时间) 检查查询。 根据建立的性能基线，检查时间是否超过 () 设置的阈值（以毫秒为单位）。 例如，在压力测试环境中，你可能已为工作负荷设置了不超过 300 毫秒的阈值，并且可以使用此阈值。 然后，可以识别超过该阈值的所有查询，重点关注每个查询及其预先建立的性能基线持续时间。 最终，业务用户关心数据库查询的总体持续时间：因此，主要侧重于执行持续时间。 收集 CPU 时间和逻辑读取等其他指标，以帮助缩小调查范围。
对于当前正在执行的语句，请检查sys.dm_exec_requests中的total_elapsed_time和cpu_time列。 运行以下查询以获取数据：
12345678910111213141516SELECTreq.session_id, req.total_elapsed_time AS duration_ms, req.cpu_time AS cpu_time_ms, req.total_elapsed_time - req.cpu_time AS wait_time, req.logical_reads, SUBSTRING (REPLACE (REPLACE (SUBSTRING (ST.text, (req.statement_start_offset/2) + 1,((CASE statement_end_offsetWHEN -1THEN DATALENGTH(ST.text)ELSE req.statement_end_offsetEND - req.statement_start_offset)/2) + 1) , CHAR(10), ' '), CHAR(13), ' '),1, 512) AS statement_textFROM sys.dm_exec_requests AS reqCROSS APPLY sys.dm_exec_sql_text(req.sql_handle) AS STORDER BY total_elapsed_time DESC;对于过去执行的查询，请检查sys.dm_exec_query_stats中的last_elapsed_time列和last_worker_time列。 运行以下查询以获取数据：
123456789101112SELECT t.text,(qs.total_elapsed_time/1000) / qs.execution_count AS avg_elapsed_time,(qs.total_worker_time/1000) / qs.execution_count AS avg_cpu_time,((qs.total_elapsed_time/1000) / qs.execution_count ) - ((qs.total_worker_time/1000) / qs.execution_count) AS avg_wait_time,qs.total_logical_reads / qs.execution_count AS avg_logical_reads,qs.total_logical_writes / qs.execution_count AS avg_writes,(qs.total_elapsed_time/1000) AS cumulative_elapsed_time_all_executionsFROM sys.dm_exec_query_stats qsCROSS apply sys.Dm_exec_sql_text (sql_handle) tWHERE t.text like '<Your Query>%'-- Replace <Your Query> with your query or the beginning part of your query. The special chars like '[','_','%','^' in the query should be escaped.ORDER BY (qs.total_elapsed_time / qs.execution_count) DESC本人提供Oracle(OCP、OCM)、MySQL(OCP)、PostgreSQL(PGCA、PGCE、PGCM)等数据库的培训和考证业务，私聊QQ646634621或微信dbaup66，谢谢！
