Wait Stats Per Query
Published: Oct 23, 2015
This was something that I have wanted to be able to do for a while. I like having wait stats to look at (I’ll do a blog about those at some point - this is for people who already know what they are)… but until Extended Events came about these were only available, to my knowledge, at the server level. This was great, but what if you wanted to know what your specific query was doing?

In this circumstance you would have to clear down your SQL Server, make sure no-one else was using it, that nothing else was running (jobs, broker etc), clear down your existing wait stats and then run your query.

Fun yes? Well now that’s no longer needed. With Extended Events and some slightly dubious code it’s possible to collect wait stats on your query itself.

So how does this work? Well, Extended Events will track wait stats per SPID and therefore what you need to do is set up a session against your SSMS SPID, run your code, stop your session, and then read in the results.

This seemed a little cumbersome to me, therefore I wrote a proc to do this for me.

NOTE: This does use xp_cmdShell in order to run. Therefore it’s best done on a test machine unless you have this on your live server. You could code this to avoid xp_cmdShell, but you’d have to do some file cleanup manually instead.

Effectively what happens is that I open a session in SSMS, therefore obtaining my SPID, and I place my code in that window.

Next, open a new window and enter the SPID of the window containing your code and hit F5.

Now you simply go back to the other window and run your code. Once the code completes you’ll see the proc has returned all the Wait Stats for the query.

In simpler terms we do as follows:

Open a new Window in SSMS and note the SPID:

Now, open another SSMS window and run my proc using the SPID you just obtained (I keep my code in a database called “serverMonitor”… you would therefore change this according to your needs):

The proc sits and waits for you to run your code.

Go back to your other window, insert some code, and run it:

select *
from AdventureWorks2012.Sales.SalesOrderDetailEnlarged


In my case I’ve just run a simple select * from a large table. I’m not expecting anything more than PAGEIOLATCH waits as I know the table isn’t in the buffer pool. I’m also not expecting many as my disks are all solid state.

As soon as the code completes you can go back to your other window and you’ll see that the proc has indeed provided you with wait stats on your query:

Good eh?

Well for any interested people, here’s my code. I don’t claim it’s idiot proof and it may well be able to be tweaked. But it works and that’s all I need.

create procedure waitStatsSPID
      
@spid int
as
       declare
@identifier varchar(25) = convert(varchar(25), abs(floor((convert(bigint, convert(varbinary(8), newID())))+1))),
                    
@sql varchar(max)

      
select @sql = '
       if exists(select * from sys.server_event_sessions where name = ''monitorWaits'
+ @identifier + ''')
              drop event session monitorWaits'
+ @identifier + ' on server

       create event session monitorWaits'
+ @identifier + '
              on server
       add event sqlos.wait_info
              (where sqlServer.session_id = '
+ convert(varchar(10), @spid) + ')
       add target package0.asynchronous_file_target
              (set filename = N''C:\temp\ee_waitStats'
+ @identifier + '.xel'',
                     metadatafile = N''C:\temp\ee_waitStats'
+ @identifier + '.xem'')
       with (max_dispatch_latency = 1 seconds)'

      
exec (@sql)

      
while not exists
       (
              
select *
              
from master.dbo.sysprocesses
              
where spid = @spid
              
and status not in ('background', 'sleeping')
              and
cmd not in
              
(
                    
'AWAITING COMMAND',
                    
'MIRROR HANDLER',
                    
'LAZY WRITER',
                    
'CHECKPOINT SLEEP',
                    
'RA MANAGER'
              
)
       )
      
begin
              waitfor
delay '00:00:00.000'
      
end

       set
@sql = 'alter event session monitorWaits' + @identifier + ' on server state = start;'

      
exec (@sql)

      
while exists
       (
              
select *
              
from master.dbo.sysprocesses
              
where spid = @spid
              
and status not in ('background', 'sleeping')
              and
cmd not in
              
(
                    
'AWAITING COMMAND',
                    
'MIRROR HANDLER',
                    
'LAZY WRITER',
                    
'CHECKPOINT SLEEP',
                    
'RA MANAGER'
              
)
       )
      
begin
              waitfor
delay '00:00:00.000'
      
end

       set
@sql = 'alter event session monitorWaits' + @identifier + ' on server state = stop;'

      
exec (@sql)

      
create table #rawEventData
      
(
              
rowID int identity primary key clustered,
              
event_data xml
      
)

      
insert into #rawEventData(event_data)
      
select cast (event_data as xml) as event_data
      
from sys.fn_xe_file_target_read_file
              
(
                    
N'C:\temp\ee_waitStats' + @identifier + '*.xel',
                    
N'C:\temp\ee_waitStats' + @identifier + '*.xem',
                     null, null
              )

      
set @sql = 'declare @dump table(dumpData varchar(max))

       insert into @dump exec xp_cmdShell ''del C:\temp\ee_waitStats'
+ @identifier + '*.xe*'''

      
exec (@sql)

      
select waits.[Wait Type],
              
sum (waits.Duration) AS [Total Wait Time (ms)]
      
from
      
(
              
select
                    
event_data.value ('(/event/@timestamp)[1]', 'DATETIME') AS [Time],
                    
event_data.value ('(/event/data[@name=''wait_type'']/text)[1]', 'VARCHAR(100)') AS [Wait Type],
                    
event_data.value ('(/event/data[@name=''opcode'']/text)[1]', 'VARCHAR(100)') AS [Op],
                    
event_data.value ('(/event/data[@name=''duration'']/value)[1]', 'BIGINT') AS [Duration]
              
from #RawEventData
      
) waits
      
where waits.op = 'End'
      
and waits.Duration > 0
      
and waits.[Wait Type] != 'NETWORK_IO'
      
group by waits.[Wait Type]
      
order by [Total Wait Time (ms)] desc

       drop table
#rawEventData
go
Leave a Comment
Your email address will not be published. All fields are mandatory.
NB: Comments will only appear once they have been moderated.

Your SQL Trainer
Kevin Urquhart

I am a SQL Server DBA, Architect, Developer, and Trainer for SQL Training. This is my blog in which I’m simply trying to share my SQL knowledge and experiences with the world.

Kevin Urquhart
SQL Server Consultant, London

Categories


Archives


Copyright © 2018 London SQL Server Training Courses @ SQL Training | Website Design From Scott Heron