查看语句运行时间异常的原因（SQLServer）

经常有开发同事反映如下情况：我有一条语句或者一个JOB昨天跑半个小时就完成了，今天怎么跑了两个小时还没有完成？ 是不是数据库出现问题了？ 数据库语句运行时间异常，其实是一个比较复杂的情况，因为数据是不断变动的，今天好好的一条语句，有可能明天运行

    经常有开发同事反映如下情况：我有一条语句或者一个JOB昨天跑半个小时就完成了，今天怎么跑了两个小时还没有完成？

是不是数据库出现问题了？

    数据库语句运行时间异常，其实是一个比较复杂的情况，因为数据是不断变动的，今天好好的一条语句，有可能明天运行就

不在预计的时间内了，这个场景是没办法完全重溯的，即便有当时的备份数据，但是当时的服务器压力是没有办法知道和营造

的；但是好在现在不是要调查昨天语句跑时间异常的原因，而是要找到现在语句运行异常的原因，现在的情况还正在进行着呢，

所以我们可以根据语句目前的情况，初步来排查一下；

    其实要考虑的问题比较多：

    1. 索引是否正常（索引是否损坏、有没有人删除索引等）；

    2. 统计信息是否过时；

    3. 语句执行计划是否发生偏移（和索引、统计信息以及数据量都有关系）；

    4. 语句是否有bug；

    5. 是否发生的阻塞；

    6. 系统资源是否遇到瓶颈；

    .........

    这么多的情况都考虑的话我们很难下手，一般解决这个问题我们都需要采用比较快的方式来做排查，以下方法主要针对5和6两

个方面进行，因为这两个方面是最常见的情况。

我们来简单模拟一下排查过程:

1. 创建测试表和数据

<span>USE</span> <span>[</span><span>master</span><span>]</span><br><span>GO</span><br><br><span>/*</span><span>***** Object:  Table [dbo].[a]    Script Date: 01/17/2012 16:46:34 *****</span><span>*/</span><br><span>SET</span> ANSI_NULLS <span>ON</span><br><span>GO</span><br><br><span>SET</span> QUOTED_IDENTIFIER <span>ON</span><br><span>GO</span><br><br><span>SET</span> ANSI_PADDING <span>ON</span><br><span>GO</span><br><br><span>CREATE</span> <span>TABLE</span> <span>[</span><span>dbo</span><span>]</span>.<span>[</span><span>a</span><span>]</span>(<br>    <span>[</span><span>id</span><span>]</span> <span>[</span><span>int</span><span>]</span> <span>IDENTITY</span>(<span>1</span>,<span>1</span>) <span>NOT</span> <span>NULL</span>,<br>    <span>[</span><span>name</span><span>]</span> <span>[</span><span>varchar</span><span>]</span>(<span>100</span>) <span>NULL</span><br>) <span>ON</span> <span>[</span><span>PRIMARY</span><span>]</span><br><br><span>GO</span><br><br><span>SET</span> ANSI_PADDING <span>OFF</span><br><span>GO</span><br><br><br><span>insert</span> <span>into</span> a <span>values</span>(<span>'</span><span>aa</span><span>'</span>),(<span>'</span><span>bb</span><span>'</span>),(<span>'</span><span>cc</span><span>'</span>)

2. 制造阻塞：开两个session，分别运行下面的语句

<span>--</span><span>Session 1</span><span><br></span><span>use</span> master<br><span>go</span><br><span>begin</span> <span>tran</span><br><span>update</span> A <span>set</span> name<span>=</span><span>'</span><span>abc</span><span>'</span> <span>where</span> id<span>=</span><span>2</span><br><br><span>--</span><span>rollback</span>

<br><br><span>--</span><span>Session 2</span><span><br></span><span>select</span> <span>*</span> <span>from</span> a 

因为Session1 的Update语句没有能够提交，所以此时Session2 过程会被阻塞

3. 分析排查：

  我们首先需要查询下此时数据库中是否存在阻塞：

<span>--</span><span>Blocked</span><span><br></span><span>select</span> <span>*</span> <span>from</span> sys.sysprocesses <span>with</span>(nolock) <span>where</span> blocked<span></span><span>0</span>

 我们看到了阻塞的记录，53阻塞了56，被阻塞的资源是：dbid 1 file 1 page 307；

 接下来我们需要知道阻塞和被阻塞的是什么语句，有两种方式：

 a. dbcc inputbuffer

 b. sys.dm_exec_sql_text

 方法一与方法二相比：

   优点：方法一能显示非活动session的语句，方法二只能查活动的session（通过sp_who2 active 能显示是否活动）；

   缺点：方法一只能一个一个查询，方法二可以多个一起查询；

方法一：

<span>--</span><span>No1:</span><span><br></span><span>dbcc</span> inputbuffer(<span>53</span>)<br><span>go</span><br><span>dbcc</span> inputbuffer(<span>56</span>)

方法二：

<span>--</span><span>No2:</span><span><br></span><span>SELECT</span><br>    S.session_id, R.blocking_session_id,<br>    S.<span>host_name</span>, S.login_name, <br>    databaseName<span>=</span><span>DB_NAME</span>(R.database_id),R.command, R.status,<br>    current_execute_sql <span>=</span> <span>SUBSTRING</span>(T.<span>text</span>,<br>                R.statement_start_offset <span>/</span> <span>2</span> <span>+</span> <span>1</span>,<br>                <span>CASE</span><br>                    <span>WHEN</span> statement_end_offset <span>=</span> <span>-</span><span>1</span> <span>THEN</span> <span>LEN</span>(T.<span>text</span>)<br>                    <span>ELSE</span> (R.statement_end_offset <span>-</span> statement_start_offset) <span>/</span> <span>2</span><span>+</span><span>1</span><br>                <span>END</span>),<br>    S.program_name,<br>    S.status,<br>    S.cpu_time, memory_usage_kb <span>=</span> S.memory_usage <span>*</span> <span>8</span>, S.reads, S.writes,<br>    S.transaction_isolation_level,<br>    C.connect_time, C.last_read, C.last_write,<br>    C.net_transport, C.client_net_address, C.client_tcp_port, C.local_tcp_port,<br>    R.start_time, <br>    R.wait_time, R.wait_type, R.last_wait_type, R.wait_resource,<br>    R.open_transaction_count, R.transaction_id<br>    <br><span>FROM</span> sys.dm_exec_sessions S<br>    <span>LEFT</span> <span>JOIN</span> sys.dm_exec_connections C<br>        <span>ON</span> S.session_id <span>=</span> C.session_id<br>    <span>LEFT</span> <span>JOIN</span> sys.dm_exec_requests R<br>        <span>ON</span> S.session_id <span>=</span> R.session_id<br>            <span>AND</span> C.connection_id <span>=</span> R.connection_id<br>    <span>OUTER</span> APPLY sys.dm_exec_sql_text(R.sql_handle) T<br><span>WHERE</span>  S.is_user_process <span>=</span> <span>1</span>  <span>--</span><span> 如果不限制此条件，则查询所有进程（系统和用户进程）</span><span><br></span><span>and</span> s.session_id <span>in</span>(<span>53</span>,<span>56</span>)

我们看到方法一两条语句都能查出来，而方法二只能查出一个语句；

到这里，我们已经能判断语句运行慢的原因是被阻塞了，我们再来查查阻塞的原因是什么，可以通过以下语句查看：

<span>select</span> request_session_id,resource_type,<span>db_name</span>(resource_database_id) <span>as</span> DBName,resource_description,<br>request_mode,request_type,request_status <span>from</span> sys.dm_tran_locks <span>where</span> request_session_id <span>in</span>(<span>56</span>,<span>53</span>)<br><span>order</span> <span>by</span> request_session_id

可以看到，56处于WAIT状态，它在等待获取1：307：1 上的一个共享锁，但是1：307：1上被53的一个排他锁占据了（GRANT代表

已获得资源，正在运行），因此56必须等待53上的排他锁释放后才能继续运行；于是我们转而调查53排他锁没有释放的原因；可能是

53需要的其他资源被其他进程占有了，在等待其他进程释放锁；也可能是因为Update语句更新的数据量过多，需要的时间比较长，不

能够及时的释放锁；还有就是我们现在的情况，没有提交事物了（语句中可以直接看到）；阻塞的排查方法都是类似的。

 

如果语句并没有被其他语句blocked呢？ 那我们需要再进一步查找的原因就是Wait了，前面已经有wait的相关查询，下面我们来查下

更具体的信息：

<span>--</span><span> wait & lock</span><span><br></span><span>select</span> lo.request_session_id <span>as</span> <span>[</span><span>Session</span><span>]</span>,<br><span>DB_NAME</span>(lo.resource_database_id) <span>as</span> Dbname,<br>lo.resource_type <span>as</span> <span>[</span><span>Type</span><span>]</span>,<br>lo.resource_description,<br>lo.request_mode,<br>lo.request_owner_type,<br>lo.request_status,<br><span>case</span> <span>when</span> lo.resource_type<span>=</span><span>'</span><span>OBJECT</span><span>'</span> <span>then</span> <span>OBJECT_NAME</span>(lo.resource_associated_entity_id)<br>     <span>when</span> lo.resource_associated_entity_id <span>IS</span> <span>NULL</span> <span>OR</span> lo.resource_associated_entity_id<span>=</span><span>0</span><br>     <span>then</span> <span>NULL</span><br>     <span>else</span> <span>OBJECT_NAME</span>(p.<span>object_id</span>) <br>     <span>end</span> <span>as</span> Associated_Entity,<br>wt.blocking_session_id,wt.resource_description<br><span>from</span> <br>sys.dm_tran_locks lo <span>with</span>(nolock)<br><span>left</span> <span>join</span> sys.partitions p <span>with</span>(nolock)<br><span>on</span> lo.resource_associated_entity_id<span>=</span>p.partition_id<br><span>left</span> <span>join</span> sys.dm_os_waiting_tasks wt <span>with</span>(nolock)<br><span>on</span> lo.lock_owner_address<span>=</span>wt.resource_address<br><span>where</span> lo.request_session_id<span>></span><span>50</span><br><span>and</span> lo.request_session_id<span>=</span><span>56</span> <br><span>order</span> <span>by</span> <span>[</span><span>Session</span><span>]</span> ,<span>[</span><span>TYPE</span><span>]</span>

上面可以看到，56在获取共享资源1：307：1时，遇到了等待，当然这里的等待还是被53阻塞了，但是等待会有多种原因的等待，我们查

一下当前的等待信息：

<span>--</span><span>current wait info</span><span><br></span><span>select</span> wait_type,<span>COUNT</span>(<span>0</span>) <span>as</span> num_waiting_tasks,<br><span>SUM</span>(wait_duration_ms) <span>as</span> total_wait_time_ms<br> <span>from</span> sys.dm_os_waiting_tasks <span>with</span>(nolock)<br><span>where</span> session_id<span>></span><span>50</span><br><span>group</span> <span>by</span> wait_type<br><span>order</span> <span>by</span> wait_type

这里可以看到是锁等待（Wait_Type），还有很多资源类型的等待，值的重点关注的有：
  Memory:CMEMTHREAD ,RESOURCE_SEMAPHORE
     CMEMTHREAD:
       说明和原因：计划缓存出现问题的标志（大量计划加入或者移出）；
       解决：     使用参数化的查询或者设置数据库强制参数化（forced parameterization）

     RESOURCE_SEMAPHORE：
       说明和原因：内存密集型查询无法获得请求的内存；其他进程消耗了太多的内存；
       解决：     为数据库添加合适的索引或者增加内存

  IO：IO_COMPLETION,ASYNC_IO_COMPLETION,WRITELOG,PAGEIOLATCH_*

  CPU: CXPACKET,SOS_SCHEDULER_YIELD
       CXPACKET:
          说明和原因：并行处理等待类型，并行同步等待；
          解决：     可以通过修改并行度的值（或者禁用）解决；
       SOS_SCHEDULER_YIELD：
          说明和原因：任务执行到时间片尾，让出调度器给其他任务运行；
          解决：     需要处理能力更好的CPU
 
  Network：ASYNC_NETWORK_IO,DBMIRROR_SEND
       ASYNC_NETWORK_IO: 网卡带宽饱和或者客户端不能及时把结果取走；
       DBMIRROR_SEND：  网络带宽不足以支持镜像事务量或者镜像数据库超出限额；

  锁阻塞：LCK_*    

我们可以统计下，我们数据库最多的20种等待类型：

<span>--</span><span>total wait info</span><span><br></span><span>select</span> <span>top</span> <span>20</span> wait_type,<span>SUM</span>(waiting_tasks_count) waiting_tasks_count,<br><span>SUM</span>(wait_time_ms)<span>as</span> total_wait_time_ms,<br><span>SUM</span>(signal_wait_time_ms) <span>as</span> total_signal_wait_time_ms<br><span>from</span> sys.dm_os_wait_stats <span>with</span>(nolock)<br><span>where</span> wait_type <span>not</span> <span>in</span><br> <span>--</span><span>system wait type</span><span><br></span>(<span>'</span><span>LAZYWRITER_SLEEP</span><span>'</span>,<span>'</span><span>REQUEST_FOR_DEADLOCK_SEARCH</span><span>'</span>,<span>'</span><span>SQLTRACE_BUFFER_FLUSH</span><span>'</span>,<br> <span>'</span><span>XE_TIMER_EVENT</span><span>'</span>,<span>'</span><span>FT_IFTS_SCHEDULER_IDLE_WAIT</span><span>'</span>,<span>'</span><span>LOGMGR_QUEUE</span><span>'</span>,<span>'</span><span>CHECKPOINT_QUEUE</span><span>'</span>,<br> <span>'</span><span>SLEEP_TASK</span><span>'</span>,<span>'</span><span>BROKER_IO_FLUSH</span><span>'</span>,<span>'</span><span>BROKER_TASK_STOP</span><span>'</span>,<span>'</span><span>BROKER_TO_FLUSH</span><span>'</span>,<span>'</span><span>BROKER_EVENTHANDLER</span><span>'</span>)<br><span>group</span> <span>by</span> wait_type<br><span>order</span> <span>by</span> total_wait_time_ms <span>desc</span>

通过这个我们可以从中看出DB等待主要集中在哪些方面，如果是在CPU、IO、Memory、Lock等上面等待时间很长，说明我们

的数据库需要做某些方面的优化了。

    以上就是从阻塞和等待方面，对运行时间异常的语句做初步排查的过程，欢迎大家拍砖。