Friday, June 29, 2012

Extended Events - an idiot's primer

Me being the idiot for having taken this long to finally tackle it, and for all the mistakes I made tonight.

Here are the basics on Extended Events:
It's fast, lightweight, and will replace Profile Traces.  You need to learn this, and now. Spend 30 minutes here and run this code, modify it, play with it.

Fortunately, there's a GUI for 2008 SSMS (the Extended Event Session Explorer), and 2012 supports it via the GUI, but ONLY IF you're hitting a 2012 server.  If you install EESE, there's no documentation.  Install it.  Bring up the Object Explorer.  Select a server.  Now go to the VIEW menu in SSMS and the first option is Show Extended Event Session Explorer.  You pretty much can only create a SQL Script, which is perfect.  Read below, then install and play.

Okay, first hurdle done.  XE (Extended Events, get used to the term) is all command line, until you move to SSMS 2012 & SQL Server 2012.  All that EESE tool does is make it easier to create your script.  A LOT easier.

Here's my basic script.
* It creates an SESSION (a "trace", using the old terminology),
* tracking 1 or many EVENTs (pretty much same as in Profiler ;each event is separate and has separate filters).
* In order to get more data from the EVENTs, you add ACTIONs (the columns in Profiler).
* You can also add PREDICATEs, which is a Filter - it acts like a Profiler Column filter and even uses the WHERE clause.
* Finally, you add a TARGET, which is where this goes.
** The two main ones to start with are the asynchronous_file_target (2012 calls it a file_event; the name I use works in both versions), which is basically a file written to disk.  Note that there is a METADATAFILE created on 2008.  YOU NEED THIS.  You can't query the code without it.  Now, under 2012, there IS NO METADATAFILE, even if you explicitly tell it so; it just won't create it.  Turns out that's a change, and for the better.  Fortunately, on the code used to parse the file(sys.fn_xe_file_target_read_file), all you have to do is leave the second parameter as NULL and it'll work.  
** There is also the RING_BUFFER, which is a fancy way of saying "save a few megabytes for it in RAM; no need to save this to disk or anything". Server reboots, it went bye-bye - not saved.  And as you save new "rows" to it, it can push out old rows.
* There is a WITH clause, which can do fancy things like server_startup, so when the server bounces it starts back up.  There are others, but to be honest most of the defaults seem quite reasonable.

You then have to START the session.  Non-intuitive, and I don't think either the XE wizard in 2012, OR the SSMS 2008 Codeplex tool does that unless you choose Start Immediately, which you honestly should stop and think about before doing.  You just did this new piece of code, find a quiet server to run it on.

So, you've started it. Congrats!  Now that it's going, you can query it!  Either way, using the Ring Buffer or the file, it's now live - but you may not see data for up to 30 seconds.  There's a thing called dispatch latency, which is a fancy way of saying "it can sit for up to X seconds before writing to buffer/disk".  Default is 30 seconds.  Default size for the file is 1gb, and I suspect there are 5 default growths.

But the query works.  Shamelessly copied from Jonathon Kehayias, who is an MVP and I believe one of The Guys when it comes to XE.  As well he should be.  This is me condensing the last 5 hours into 5 minutes.  I had to skip some parts.

ONE OTHER VERY IMPORTANT THING:
this code isn't working quite right for me, but it could be because I've stared at it for 5 hours now (there's your learning curve; probably closer to 2-3 before it clicks).  For some reason, it's filtering my RPC calls.  I'll try and figure it out in the morning.



--Drop old session if it exists
IF EXISTS(SELECT * FROM sys.server_event_sessions WHERE name='web_user_XEv')
    DROP EVENT SESSION [web_user_XEv] ON SERVER;
--Create the new session
CREATE EVENT SESSION [web_user_XEv]
ON SERVER
--One “add event” per type of event you want to capture; filters MUST be applied to each!
ADD EVENT sqlserver.rpc_completed
(
--this part is optional; add other things you want returned in the XML
     ACTION (sqlserver.sql_text,sqlserver.username,sqlserver.client_app_name)
--a predicate – this limits things. No examples on whether it’s unicode or not; this sort of works.
-- you could also filter on the app name, etc, etc, etc.
     WHERE (((sqlserver.username<>'my.name')) and ((sqlserver.username<>N'the.other.guys.name')))
)
--How we actually save the data.  This saves to a file.
--This particular code is 2008/2012; it becomes “file_event” in 2012, but this works in both
ADD TARGET package0.asynchronous_file_target(
--the metadatafile is NOT RETURNED in 2012, but you don’t need it; just change the call that reads the log to NULL
-- And without having the metadata file in 2008, the data file is useless; you can’t query.
-- However, even in 2008 you don’t actually NEED to create the metadatafile; it will do it for you. So rerun your CREATE script and use that file.
-- So I guess the metadata call is sort of like the appendix?
     SET filename='c:\sql_log\web_user.xel', metadatafile='c:\sql_log\web_user.xem'
--Lots of options here, but the defaults are fine. You don’t even need the latency.
-- However, one you probably want is server_side.  That autorestarts it when the box comes up. Dispatch Latency says it can sit in RAM for up to 30 seconds before being written.
    WITH (max_dispatch_latency = 30 SECONDS)
go

--Actually STARTS the trace
ALTER EVENT SESSION [web_user_XEv] ON SERVER STATE = START
GO

-------do whatever you want here.  You’re tracing!  Congrats!- --------------

--Now stop the trace.
ALTER EVENT SESSION [web_user_XEv] ON SERVER STATE = STOP
go

--Basic query to pull out data. You CAN (and should) run this while the XE is running.  Clever, eh?
SELECT
--          event_data.value('(event/@name)[1]', 'varchar(50)') AS event_name,  --“rpc_completed”, etc
            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,
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_user*.xel', 'c:\sql_log\web_user*.xem', NULL, NULL)
)a

No comments: