THE SQL Server Blog Spot on the Web

Welcome to SQLblog.com - The SQL Server blog spot on the web Sign in | |
in Search

Jamie Thomson

This is the blog of Jamie Thomson, a freelance data mangler in London

Capturing query and IO statistics using Extended Events

The commands

SET STATISTICS TIME ON
SET STATISTICS
IO ON

 

return information about query executions and are very useful when doing performance tuning work as they inform how long a query took to execute and the amount of IO activity that occurred as a result of that query.

These are very effective features however to my mind they do have a drawback in that the information they provide is not accessible in the actual query window from which the query was executed. This means the results cannot be collected, stored in a table, and then queried – such information would have to be manually copied and pasted from the messages pane into (say) a spreadsheet for further analysis.

This is dumb. I’m a SQL Server developer, I want my data available so that I can bung it into a table in SQL Server and issue queries against it. That is why, a couple of weeks ago, I submitted a request to Microsoft Connect entitled Access to STATS TIME & STATS IO from my query in which I said:

I recently was doing some performance testing work where I was evaluating the affect of changing various settings on a particular query. I would have liked to simply run my query inside a couple of nested loops in order to test all permutations but I could not do that because every time I executed the query I had to pause so I could retrieve the stats returned from STATISTICS IO & STATISTCS TIME and manually copy and paste (yes, copy and paste) the information into a spreadsheet.

This feels pretty dumb in this day and age. Why can we not simply have access to that same information within my query? After all, we have @@ROWCOUNT, ERROR_MESSAGE(), ERROR_NUMBER() etc... that provide very useful information about the previously executed statement, how about @@STATISTICS for returning all the IO & timing info? We can parse the text returned by that function to get all the info we need.
Better still, provide individual functions e.g.:
@@QUERYPARSETIME
@@QUERYCOMPILETIME
@@QUERYEXECUTIONTIME
@@SCANCOUNT
@@LOGICALREADS
@@PHYSICALREADS
@@READAHEADREADS

Ralph Kemperdick noticed my submission and correctly suggested that the same information could be accessed using Extended Events. Based on this I’ve written a script (below) that issues a series of queries against the AdventureWorks2012 sample database, captures similar stats that would be captured by SET STATISTICS then presents them back at the end of the query. Here are those results:

image

The information is not as comprehensive as what you would get from SET STATISTICS (no Read-Ahead Reads for example, and no breakdown of IO per table) but should be sufficient for most purposes.

You can adapt the script accordingly for whatever information you want to capture, the important part of the script is the creation of the XEvents session for capturing the queries, then reading and shredding the XML results thereafter.

Hope this is useful!

@Jamiet

UPDATE: Turns out you don't need all of this. I've just been informed that Richie Rump has written a parser at http://statisticsioparser.com/ that does all of this for you. Simple paste in your STATISTICS IO output and press the button - it will do all the hard work for you and give you the results back in a nice readable graph. You can paste in multiple results at once too.

--Create the event session
CREATE EVENT SESSION [queryperf] ON SERVER
ADD EVENT sqlserver.sql_statement_completed
ADD TARGET package0.event_file(SET filename=N'C:\temp\queryperf.xel',max_file_size=(2),max_rollover_files=(100))
WITH MAX_MEMORY=4096 KB,EVENT_RETENTION_MODE=ALLOW_MULTIPLE_EVENT_LOSS,
            
MAX_DISPATCH_LATENCY=120 SECONDS,MAX_EVENT_SIZE=0 KB,
            
MEMORY_PARTITION_MODE=NONE,TRACK_CAUSALITY=OFF,STARTUP_STATE=ON);

--Set up some demo queries against AdventureWorks2012 in order to evaluate query time & IO
USE AdventureWorks2012
DECLARE    @SalesPersonID INT;
DECLARE    @salesTally INT;
DECLARE    mycursor CURSOR FOR
SELECT
soh.SalesPersonID
FROM   Sales.SalesOrderHeader soh
GROUP  BY soh.SalesPersonID;
OPEN mycursor;
FETCH NEXT FROM mycursor INTO @SalesPersonID;
ALTER EVENT SESSION [queryperf] ON SERVER STATE = START;
WHILE @@FETCH_STATUS = 0
BEGIN
       DBCC
FREEPROCCACHE;
      
DBCC DROPCLEANBUFFERS;
      
CHECKPOINT;
      
SELECT @salesTally = COUNT(*)
      
FROM Sales.SalesOrderHeader  soh
      
INNER JOIN Sales.[SalesOrderDetail] sod        ON  soh.[SalesOrderID] = sod.[SalesOrderID]
      
WHERE SalesPersonID = @SalesPersonID
      
FETCH NEXT FROM mycursor INTO @SalesPersonID;
END
CLOSE
mycursor;
DEALLOCATE mycursor;
DROP EVENT SESSION [queryperf] ON SERVER;

--Extract query information from the XEvents target
SELECT q.duration,q.cpu_time,q.physical_reads,q.logical_reads,q.writes--,event_data_XML,statement,timestamp
FROM   (
      
SELECT  duration=e.event_data_XML.value('(//data[@name="duration"]/value)[1]','int')
       ,      
cpu_time=e.event_data_XML.value('(//data[@name="cpu_time"]/value)[1]','int')
       ,      
physical_reads=e.event_data_XML.value('(//data[@name="physical_reads"]/value)[1]','int')
       ,      
logical_reads=e.event_data_XML.value('(//data[@name="logical_reads"]/value)[1]','int')
       ,      
writes=e.event_data_XML.value('(//data[@name="writes"]/value)[1]','int')
       ,      
statement=e.event_data_XML.value('(//data[@name="statement"]/value)[1]','nvarchar(max)')
       ,      
TIMESTAMP=e.event_data_XML.value('(//@timestamp)[1]','datetime2(7)')
       ,       *
      
FROM    (
              
SELECT CAST(event_data AS XML) AS event_data_XML
              
FROM sys.fn_xe_file_target_read_file('C:\temp\queryperf*.xel', NULL, NULL, NULL)
              
)e
      
)q
WHERE  q.[statement] LIKE 'select @salesTally = count(*)%' --Filters out all the detritus that we're not interested in!
ORDER  BY q.[timestamp] ASC
;

Published Wednesday, March 05, 2014 5:19 PM by jamiet

Comment Notification

If you would like to receive an email when updates are made to this post, please register here

Subscribe to this post's comments using RSS

Comments

 

Scott Duncan said:

This is just the modern way of running Profiler or SQL Trace. Useful, but it doesn't address the original issue.

March 5, 2014 3:50 PM
 

jamiet said:

Hi Scott,

Agree that it doesn't totally replace set stats io/time but for a lot of situations it may be a sufficient replacement.

March 6, 2014 2:00 AM
 

Greg Linwood said:

This data used to be available via the sql client's command object infomessages method, though I haven't done it for over a decade so things might have changed more recently.

In the old RDO, ADO days, you'd run your query & then after it had completed you could call the infomessages method to get the text based output from set statistics or any other output text, though it would require a little parsing to format & store in a structured way.

It was also possible (though klunky) from SQL 2005 to connect to the SQLTrace events api, so xevents really just makes this process more convenient than it was previouly

March 6, 2014 2:38 AM

Leave a Comment

(required) 
(required) 
Submit

This Blog

Syndication

Powered by Community Server (Commercial Edition), by Telligent Systems
  Privacy Statement