SQLServer中使用扩展事件获取Session级别的等待信息及SQLServer 2016中Session级别等待信息的增强

什么是等待

简单说明一下什么是等待：

当应用程序对sql server发起一个session请求的时候，这个session请求在数据库中执行的过程中会申请其所需要的资源，

比如可能会申请内存资源，表上的锁资源，物理io资源，网络资源等等，

如果当前session运行过程中需要申请的某些资源无法立即得到满足，就会产生等待。

sql server会以不用的方式来展现这个等待信息，比活动session的等待信息，实例级的等待信息等等。

sql server中，等待事件是作为dba进行troubleshooting的重要参考信息之一，sql server中可以通过多中方式来获取等待信息。

但是对于sql server 2016之前的版本来说，不管是活动session级别的等待和实例级的等待，参考意义都有限，

更多的时候是想要更加详细的且可以事后分析的等待，这就需要收集那些曾经已执行过的session产生的等待信息，也就是特定session等待信息的历史记录

本文重点介绍使用扩展事件来捕获等待信息，但不介绍扩展事件本身的使用，重点放在如何使用扩展事件来获取想要的等待事件信息。

需要对扩展事件有一定的了解。

等待信息的获取途径

在sql server中有一个系统视图sys.dm_os_wait_stats记录了自数据库服务启动以来累积产生的等待信息，

如下图，这个结果是实例级的，也就是记录的整个数据库服务器所有的等待事件的累积。

多数时候参考意义不是很大，比如某一天的网络延时很高，sys.dm_os_wait_stats中累计记录了大量的async_network_io等待信息。

但是到了第二天或者什么时候，网络变好了，但是sys.dm_os_wait_stats中记录的async_network_io等待信息是不变的

也就是说sys.dm_os_wait_stats无法反映实时等待情况。

当然要获取实时的等待信息也简单，记录两个时间点之间sys.dm_os_wait_stats中等待时间的差值，可以间接地反映出来某一段时间的数据的等待信息。

但是这个信息仍然比较粗略，依旧是实例级的，某些时候依旧是不足够作为参考的。

另外一个是通过sys.dm_exec_requests这个系统视图的wait_type，wait_time等获取活动session的等待信息

如截图，但是这个是活动session的信息，当session完成之后，它的等待信息就看不到曾经都产生了那些等待，分别是多久。

也就说，你无法追溯历史上某一个session或者某一个sql（存储过程）执行过程中的都产生了什么类型的等待，等待了多长时间。

实话说，不管是sys.dm_os_wait_stats还是sys.dm_exec_requests，在正常情况下，获取到的等待信息实用价值都是不高或者是适用场景有限。

更多的时候我们是想要更细一级的等待，比如某一个login、某一部分session、甚至某些特定的sql（存储过程）的执行过程中产生的等待信息。

举个实际例子，数据库又10个login给10个不同的应用程序访问，其中只有1个应用程序端反馈说访问数据库慢，或者有性能问题，其他login都反馈正常

那么很有可能是这个login请求自己的问题，此时就需要针对这一个login的情况进行针对性分析，而不是在实例级分析诊断。

如果能够拿到这个login执行的session的等待情况，或者这个login某些特定的数据库对象的执行过程中的等待信息，对定位问题的针对性的就比较强了。 

本文就以此为切入点，针对如何获取session级别的等待信息展开说明和演示。

sql server 2016中获取session级别的等待信息

在sql server 2016中，获取session级别的等待信息是比较方便的，有直接的系统视图sys.dm_exec_session_wait_stats可以使用

当前情况下，想要知道某一个session的等待信息就很简单了，

在sql语句开始的时候把当前session的等待信息记录下来

在sql语句结束的时候把当前session的等待信息再次记录出来

计算两次等待信息的差值，就可以知道当前session运行的过程中有哪些等待，分别是多少。

　　sqlserver开发团队可能也意识到了对于等待信息，更多的时候，需要的是较为具体的等待，而不是一个笼统的实例级的等待

　　因此在sql server 2016中增加了sys.dm_exec_session_wait_stats这个支持统计session级别的等待的视图

　　很不幸的sql server2016之前的版本中是没有这个系统视图可以很方便地记录session级别的等待。

　　但是可以借助扩展事件来实现类似的功能。

使用扩展事件来捕获session级别的等待信息

因为这里是是用扩展事件来实现的，这里要求读者要对扩展事件有一个基本的认识，扩展事件本身就不多说了。

上代码，启动一个扩展事件，来记录执行时间超过三秒的sql语句，其执行过程中等待时间大于0的等待事件信息。

当然这个捕获的信息可以加上各种过滤条件。具体参考代码备注。

if exists(select * from sys.server_event_sessions where name='collectionsessionwaitstats')
 drop event session collectionsessionwaitstats on server;
go
-- 创建事件会话 
create event session collectionsessionwaitstats on server  
add event sqlserver.rpc_completed
( 
  action
  (
    sqlos.task_time,
    sqlserver.database_name,
    sqlserver.nt_username,
    sqlserver.username,
    sqlserver.sql_text,
    sqlserver.session_id,
    sqlserver.transaction_id
  ) where [duration]>=3000000
), 
add event sqlserver.sql_batch_completed
( 
  action
  (
    sqlos.task_time,
    sqlserver.database_name,
    sqlserver.nt_username,
    sqlserver.username,
    sqlserver.sql_text,
    sqlserver.session_id,
    sqlserver.transaction_id
  ) where [duration]>=3000000
),
add event sqlos.wait_info
(
  action 
  (
    sqlos.task_time,
    sqlserver.database_name,
    sqlserver.nt_username,
    sqlserver.sql_text,
    sqlserver.username,
    sqlserver.session_id,
    sqlserver.transaction_id
  ) where session_id>50 
      and opcode=1 
      and duration>0
      and sql_text not like '%sp_mscdc_capture_job%' --排除某些信息
      --and username = '' --限定只记录某些信息
),
add event sqlos.wait_info_external
(
  action
  (
    sqlos.task_time,
    sqlserver.database_name,
    sqlserver.nt_username,
    sqlserver.username,
    sqlserver.sql_text,
    sqlserver.session_id,
    sqlserver.transaction_id
  ) where  session_id>50 
      and opcode=1 
      and duration>0
      and sql_text not like '%sp_mscdc_capture_job%'
      --and username = ''
)
add target package0.event_file
( 
  set filename=n'd:\xeventfiles\collectionsessionwaitstats',
  max_file_size=(1024),  
  max_rollover_files=(10) 
)
with ( 
    max_memory=4096 kb,      
    event_retention_mode=allow_single_event_loss,
    max_dispatch_latency=30 seconds,
    max_event_size=0 kb,      
    memory_partition_mode=none,   
    track_causality=off,      
    startup_state=on
  )
go
-- 启用（停止）事件会话（start / stop） 
alter event session collectionsessionwaitstats on server state=start 
go

是用扩展事件收集的session级别的等待信息有以下几个特点

1，sessionid是可以重复的

　　举例说明就是:比如一个sessionid = 80的session，可以第一次执行一个sqla，第二次执行一个sqlb.

　　同时这两个sql的执行与其执行过程中产生的等待信息都可以被捕获出来

2，同一个时间段内，一个同一个sessionid不可能同时执行，

　　比如16：46：36秒到16：46：46秒到这个时间内，sessionid = 80的session正在执行，扩展事件捕获到了其产生的等待信息

　　但是在16：46：36秒到16：46：46这个时间段内，不可能有另外一个sessionid = 80也在执行，这个逻辑不难理解

为什么要特意说明这个问题？

因为扩展事件收集到的事件信息中sql语句完成事件（rpc_completed或者sql_batch_completed）与产生的等待之间，没有一个直接的对应关系。

怎么理解？动起手来才能发现问题，我是这个纠结了大半天，截图示例。

如下截图，扩展事件捕获到的两个目标事件的sessionid都是58，但是执行的sql是不一样的，

如下截图是不区分事件类型，捕获到的所有的事件信息。

也就是上面说的，对于58号session:

第一次运行了select count(1) from testcollectionsessionwaitstats

第二次运行了select count(1) from testcollectionsessionwaitstats where id>10

两次运行的sql一致或者不一致问题不大，关键是捕获到的等待事件信心的sessionid也是58，怎么区分产生的事件是归属于哪一次的运行？

比如58号session运行两次sql，产生了10条等待信息，怎么区分这10条等待信息哪些归属于第一次运行生成的，哪些归属于第二次运行生成的？

这个就依靠上面说的第二点“同一个时间段内，一个同一个sessionid不可能同时执行”

对于同一个sessionid，在sql_batch_completed事件中，从时间的维度来看

小于第一次sql_batch_completed事件完成时间的必然是58号session第一次执行生成的

大于第一次sql_batch_completed事件完成事件的且小于第二次sql_batch_completed的必然是58号session第二次执行生成的

有了这个理论基础，我们统计session级别的等待就比较容易了，相信这个逻辑的实现并不难。

如下图是58号session执行某sql语句产生的等待详细信息，可以看到多次产生了cxpacket和 pageiolatch_sh等待

鉴于截图问题，下面还有另外一个同样是58号session的执行另外一个sql捕获到的等待信息

这个统计办法就是上面提到的，在两次sql_batch_completed事件中，虽然等待事件的sessionid一样，

但是其发生的时候是处于当前事件的sql_batch_completed之前，上一次sql_batch_completed之后，

这样就可以完美地匹配到sql_batch_completed事件与其对应的wait_info事件。

在这种情况下，统计得到类似于sql server 2016中的sys.dm_os_wait_stats的结果也就不难了。

与sys.dm_os_wait_stats 等待信息的结果相比，上述通过扩展事件获取的等待信息，是不是更加详细和具体？

比如对于cxpacket等待时间，

不难发现，如果计算计算其产生的次数（count），就类似于sys.dm_os_wait_stats 中的waiting_tasks_count，计算其产生的总时间（sum），就类似于wait_time_ms

但是上述时间的信息已经细化到session级别了，比sys.dm_os_wait_stats 中的等待信息更有参考价值。
对于问题的诊断和分析，也会是更加有效。

上述统计结果的sql语句

-- parse the xml to show rpc_completed,sql_batch_completed details
if object_id('tempdb..#t1') is not null
  drop table #t1
select 
  event_xml.value('(./action[@name="session_id"]/value)[1]', 'int') as session_id,
  event_xml.value('(./@timestamp)', 'varchar(1000)') as timestamp,
  event_xml.value('(./data[@name="statement"]/value)[1]', 'varchar(max)') as statement,
  event_xml.value('(./data[@name="batch_text"]/value)[1]', 'varchar(max)') as batch_text,
  event_xml.value('(./@name)', 'varchar(1000)') as event_name,
  event_xml.value('(./data[@name="duration"]/value)[1]', 'bigint') as duration,
  event_xml.value('(./data[@name="cpu_time"]/value)[1]', 'bigint') as cpu_time,
  event_xml.value('(./data[@name="physical_reads"]/value)[1]', 'bigint') as physical_reads,
  event_xml.value('(./data[@name="logical_reads"]/value)[1]', 'bigint') as logical_reads,
  event_xml.value('(./action[@name="username"]/value)[1]', 'varchar(max)') as username
into #t1
from (
    select cast(event_data as xml) xml_event_data 
    from sys.fn_xe_file_target_read_file(n'd:\xeventfiles\collectionsessionwaitstats*', null, null, null)
   ) as event_table
cross apply xml_event_data.nodes('//event') n (event_xml)
where event_xml.value('(./@name)', 'varchar(1000)') in ('rpc_completed','sql_batch_completed')
order by event_name
-- parse the xml to show wait_info,wait_info_external details
if object_id('tempdb..#t2') is not null
  drop table #t2
select 
  cast(event_xml.value('(./@timestamp)', 'varchar(1000)') as datetime2) as timestamp,
  event_xml.value('(./data[@name="duration"]/value)[1]', 'bigint') as duration,
  event_xml.value('(./action[@name="session_id"]/value)[1]', 'int') as session_id,
  event_xml.value('(./data[@name="wait_type"]/text)[1]', 'varchar(200)') as wait_type
into #t2
from (
    select cast(event_data as xml) xml_event_data 
    from sys.fn_xe_file_target_read_file(n'd:\xeventfiles\collectionsessionwaitstats*', null, null, null)
   ) as event_table
   cross apply xml_event_data.nodes('//event') n (event_xml)
where event_xml.value('(./@name)', 'varchar(1000)') in ('wait_info','wait_info_external')
if object_id('tempdb..#t3') is not null
  drop table #t3
select 
  a.session_id          as sessionid,
  isnull(statement,batch_text)  as sqltext,
  a.duration            as totalexecutetime,
  cast(a.timestamp as datetime2)  as completedtime,
  cast(b.timestamp as datetime2)  as waittypestarttime,
  b.wait_type            as waittype,
  b.duration            as waitduration
into #t3
from #t1 a inner join #t2 b on a.session_id = b.session_id
  and b.timestamp < a.timestamp 
  and b.timestamp>(
             select top 1 timestamp from #t1 c 
             where a.session_id = a.session_id and a.timestamp > b.timestamp
             order by a.timestamp
          )
select 
  case when rn = 1 then sessionid else null end as sessionid,
  case when rn = 1 then sqltext else null end as sqltext,
  case when rn = 1 then totalexecutetime else null end as totalexecutetime,
  completedtime as completedtime,
  waittype,
  waittypestarttime as waittypestarttime,
  waitduration
from 
(
  select row_number()over(partition by sessionid,sqltext,totalexecutetime,completedtime order by completedtime,waittypestarttime) as rn,
  * from #t3
)

当然该语句仅供参考，目的是为了收集session级的统计信息，当收集到session级别的统计信息之后，具体的统计方式也不难。

总结

　　　等待事件可以帮助我们诊断sql server上的一些资源瓶颈，对于问题的处理和解决有着比较重要的参考意义，如果能够细化地收集等待事件，对于解决问题的参考意义会更大。

　　　本文通过一个简单的示例，使用扩展事件来收集sql server中一些特定场景下的等待信息，来更加有针对性地进行问题的诊断和识别，使得问题的分析更加高效和具有针对性。

以上所述是小编给大家介绍的sqlserver中使用扩展事件获取session级别的等待信息及sqlserver 2016中session级别等待信息的增强，希望对大家有所帮助