Wednesday, July 25, 2012

Extended Events - climbing the learning curve

I recently spent an evening climbing the learning curve on XE (Extended Events), not the least of which because it acted slightly differently between SQL Server 2008 and SQL Server 2012.  I'd initially got it working, but couldn't reproduce that success for another couple of hours because I was running the code on 2008 (which lacks certain events that 2012 has - doh!).


Here's what I've learned, mostly here as a basic HOWTO, but also to remind me later.


1) It's actually pretty easy!  
2) It's the future - Profiler as we know it is going away (but you have a couple of years).  This is the replacement.
3) Jonathan Kehayias is awesome. He's gone through a bunch of pain - use his lessons learned.
4) SSMS 2012 offers it natively.  There's a plugin for SSMS 2008/R2 (Extended Event Session Explorer) that adds an option under the "View" menu.  Yes it works, but use it to assist what you're doing, don't just be the "GUI guy".
5) BOL is pretty good, but some of the obvious pages are hidden.  http://msdn.microsoft.com/en-us/library/bb630284(v=sql.105).aspx is a good example. (Somehow hadn't seen it before today)
6) Once you go through an example, all the giant blocks of code on the web make perfect sense.  That alone is a good reason to go through this exercise.


Here's an example I'm using now  You can run just this first block of code, pop open a new window, run a command, come back and see what happens.  Go on do it, I'll wait.  This works in 2008 and 2012.


CREATE EVENT SESSION [web_users_XE] ON SERVER
ADD EVENT sqlserver.rpc_completed
(
    ACTION(sqlserver.sql_text,sqlserver.username)
    WHERE ([sqlserver].[username]<>'web_users')
)
ADD TARGET package0.asynchronous_file_target(SET filename=N'C:\web_users_XE.xel'
, metadatafile='c:\web_users_XE.xem')
WITH (STARTUP_STATE=OFF)
GO
ALTER EVENT SESSION [web_users_XE] ON SERVER STATE = START
go
--at this point open a new window and run a command or two, hit an SP if you can...
sp_help
go
waitfor delay '00:00:30'
go
ALTER EVENT SESSION [web_users_XE] ON SERVER STATE = STOP
go
DROP EVENT SESSION [web_users_XE] ON SERVER;



--2008


So what's that mean and do?  Let's cover one part at a time.


CREATE EVENT SESSION [web_users_XE] ON SERVER 

pretty explanatory.  mandatory to create it. this creates the actual session.


ADD EVENT sqlserver.rpc_completed(
Now let's see: there are sessions, events, actions, and targets.  The SESSION is like the full sql trace.  The EVENTs are just like Trace Events (RPC:Completed, etc). There's even a table in 2012 that gives you a "this in trace is this in XE".  This is RPC:Completed.


    ACTION(sqlserver.sql_text,sqlserver.username)

what are we going to save? ACTIONS are "columns" in the trace (textdata, etc).  So here we savehe SQL_Text and the Username of the user running the query.  Note that this is for this particular event.  Which means you can do stuff like "event A you save these fields, for event B you save these other fields", etc, etc.


    WHERE ([sqlserver].[username]='web_users')
our filter - for this EVENT, only save from user "web_users".  As with the ACTION, it's per event.


ADD TARGET package0.event_file(SET filename=N'C:\SQL_Log\web_users_XE.xel')
OR

ADD TARGET package0.asynchronous_file_target(SET filename=N'C:\web_users_XE.xel'
, metadatafile='c:\web_users_XE.xem')


targets are "where the data goes".
Wait, why are there 2 versions?  The one in the block of code runs in both 2008/2012.  But the new name is "event_file".  Also, in 2008 you needed a metadata file to be able to parse it; they got rid of that in 2012.  It WILL NOT CREATE ONE, even if specified.  Nor do you need it to parse.
Targets: The 3 most-common are ring, file, and histogram.  
* File is a file. It's XML so it needs to be parsed, but easy enough.
* Ring is a first-in-first-out set of memory.  As you save to it, older things get kicked out.
* Histogram is a series of buckets, grouped by whatever you choose.  Why is that useful?  Kehayias does a clever example with object_id and page splits.  Everytime the split occurs, it either adds or increments a bucket with the object_id and count.  So rather than having to parse a list of events and group to see which objects are used, it's already done by the histogram - just see what buckets have the highest count, and that gives you the object ID.


WITH (STARTUP_STATE=OFF)
should this automatically start when the server starts?


ALTER EVENT SESSION [web_user_XE] ON SERVER STATE = START
actually start the session.

sp_help
Run something so we have an event.


waitfor delay '00:00:30'
There can be a 30 second delay before things are written to the file (to be lower-impact, it waits until a buffer fills).  There's a setting for this, but the default is 30 seconds.


ALTER EVENT SESSION [web_user_XE] ON SERVER STATE = STOP
stop the session.  It still exists, it's just not running.

DROP EVENT SESSION [web_users_XE] ON SERVER;
drop the session entirely.


Now, how do we parse it?  Parts cribbed from Kehayias again, notably getting the sql_text.
SELECT 
event_data.value('(event/@name)[1]', 'varchar(50)') AS event_name,
DATEADD(hh, DATEDIFF(hh, GETUTCDATE(), CURRENT_TIMESTAMP), 
event_data.value('(event/@timestamp)[1]', 'datetime2')) AS [timestamp],
event_data.value('(event/data[@name="cpu"]/value)[1]', 'int') AS [cpu],
        event_data.value('(event/data[@name="duration"]/value)[1]', 'bigint') AS [duration],
        event_data.value('(event/data[@name="reads"]/value)[1]', 'bigint') AS [reads],
        event_data.value('(event/data[@name="writes"]/value)[1]', 'bigint') AS [writes],
event_data.value('(event/action[@name="username"]/value)[1]', 'varchar(50)') AS username,
event_data.value('(event/action[@name="client_app_name"]/value)[1]', 'varchar(50)') AS application_name,
event_data.value('(event/action[@name="attach_activity_id"]/value)[1]', 'varchar(50)') AS attach_activity_id,
        REPLACE(event_data.value('(event/action[@name="sql_text"]/value)[1]', 'nvarchar(max)'), CHAR(10), CHAR(13)+CHAR(10)) AS [sql_text],
        event_data
FROM 
 (
 SELECT CAST(event_data AS xml)  AS 'event_data'
FROM sys.fn_xe_file_target_read_file('c:\sql_log\web_users*.xel', 'c:\sql_log\web_users*.xem', NULL, NULL)
)a ORDER BY DATEADD(hh, DATEDIFF(hh, GETUTCDATE(), CURRENT_TIMESTAMP), 
event_data.value('(event/@timestamp)[1]', 'datetime2')) 

Since it's XML, you need to parse it.  We convert it to XML from binary data, then use "value" to extract info.  One change between 2012 and 2008 is fn_xe_file_target_read_file.  On 2008 you need the metadatafile location.  On 2012 you don't need it, but it won't complain if it's there.

THAT'S IT!
Man, didn't that look more difficult?

No comments: