Showing posts with label xe. Show all posts
Showing posts with label xe. Show all posts

Tuesday, June 16, 2026

Updated "Sev10" Extended Event for logging errors that your apps are throwing and hiding

 Followup post to https://thebakingdba.blogspot.com/2023/02/severity-10-using-extended-events-to.html


I decided to try and improve the two different sev10s I do - these are SQL Server Extended Events that look at the sqlserver.error_reported with a severity>10 (It was originally 10 but that one is so incredibly chatty). This saves to memory (10mb limit, but it also only seems to save 1000 rows), and then this rips it down. This should now work on Azure SQL Database, Azure SQL Managed Instance, and regular ole SQL Server. This post also updates my gist, so the old post has been updated.



Thursday, February 23, 2023

Severity 10 - using Extended Events to get code errors

I wish I knew whom to thank for this.  An absolute genius idea. Probably Ozar, possibly Bertrand, could be White or a bunch of other #SQLFamily.  Warning: once you use this, you'll want it on all your servers. 

Premise: run an Extended Event looking for all errors over Severity 10, saving in a 10mb memory buffer within the SQL Server instance. Keep the rolling last errors so you have a decent amount of history. I believe the original was Severity 10 and above, but that one was too chatty for me, whereas 11+ seems to be ideal. But I refer to it as my "Sev10" code, so here we are. This includes all sorts of stuff you won't normally see - errors from stored procedures, errors in replication, errors in SSMS, etc. 

Testing it is easy: create session & start it, run "select 1/0", then run the query.

I do have a version that I run that saves logs out, but honestly, that's a different post. This Xevent uses 10mb from the Ring Buffer, constantly filling and keeping the last 10mb of errors. Performance hit seems minimal, and we're doing millions of transactions a day.

Performance has always been the kicker on this - using Xquery directly against the ring buffer is slow as heck, and even after solving that via temp tables, I still ran into problems with one particular server. That made me realize I don't appear to have posted this. By splitting it via NODE to multiple rows to a temp table, then querying the temp table to shred the XML, the performance is vastly improved.  In my case, from 8 minutes to 16 seconds. And on most servers, under 5. 

Other thoughts - you might consider adding another WHERE clause to the ADD EVENT; maybe filter end-users' machines or SSMS. I like having it, but you do you. Turns out SSMS is damn chatty sometimes, also. "View server state permission was denied " and "Cannot drop the table '#SVer'" abound.

Want to run this in Azure SQL DB? Sure, just do it against each database, replacing the "ON SERVER" with "ON DATABASE". The table names you query against change slightly (it's commented), and the time zone calculation doesn't work yet. Booooooooo.

I'm working on a collector, just haven't finished yet.

Bonus! Frames! Take the Frames provided in the Event_Data, and go use their amazing code to tell you exactly what piece of code in what function/stored procedure, and what line, caused the issue. Is it in a stored procedure calling a stored procedure calling a function? This will tell you where and what. Genius, and kudos to Tom.  https://straightforwardsql.com/posts/investigating-errors-with-extended-events/

Cheers!


Thursday, May 16, 2013

[Extended Events] list of predicates that you can use to filter actions

I've been using XE lately to get a list of servers that connect to a server I'm going to upgrade (see http://thebakingdba.blogspot.com/2013/04/extended-events-what-servers-are.html).  That way I know what the downstream effects are beforehand.

However, these are busy servers - even with connection pooling, we can get hundreds of connections a minute. Which means even minimal logging will get big, fast.

So there are two ways to prevent that:
  1. Predicates to filter before it hits the target
  2. Using a histogram to store in buckets.
However, a histogram can only store one value and a count.  I haven't figured a way to combine the fields (and according to Jonathan Kehayias you can't), so I requested Microsoft add a multi-field histogram (which got closed as Won't Fix: http://connect.microsoft.com/SQLServer/feedback/details/785063/extended-events-a-better-histogram-multiple-value-fields)

So, back to  #1, and looking at Predicates. 

Fortunately, I found this blog post which has a lot of details about it:
http://blogs.msdn.com/b/extended_events/archive/2010/06/24/today-s-subject-predicates.aspx
(yup, a 2-year-old post that's now incredibly relevant)


Specifically,
 

SELECT name, description,
    (SELECT name FROM sys.dm_xe_packages WHERE guid = o.package_guid) package
FROM sys.dm_xe_objects o
WHERE object_type = 'pred_compare'
ORDER BY name


Which lead me to:
 
sqlserver.like_i_sql_ansi_string
sqlserver.like_i_sql_unicode_string


From the blog post:
"Calling a pred_compare directly follows this syntax:
package_name.pred_compare(field/pred_source, value)
[...]ADD EVENT wait_info (WHERE package0.greater_than_max_int64(duration, 500)
 "


Okay, I can do that.

 WHERE (
              (sqlserver.like_i_sql_unicode_string(sqlserver.client_hostname,N'laptop%'))
              )

which gives me everything from our laptops.  Close.  Can I do a NOT LIKE?



 WHERE (
              (NOT sqlserver.like_i_sql_unicode_string(sqlserver.client_hostname,N'laptop%'))
              )


Which, yes, works.  
So my query to look for logins not from our laptops, and excluding certain servers, looks like...

CREATE EVENT SESSION [Logins] ON SERVER
ADD EVENT sqlserver.login(
ACTION(sqlserver.client_hostname,sqlserver.client_app_name,sqlserver.database_name)
WHERE ([sqlserver].client_hostname NOT LIKE '%-SERV-%')
              AND (NOT sqlserver.like_i_sql_unicode_string(sqlserver.client_hostname,N'laptop%'))
              )
ADD TARGET package0.ring_buffer(SET max_memory = 4096)

And, typing this in... I see I'm already excluding using a LIKE.  Why'd I go through all this effort again?  Um, knowledge, I guess?  : )

Wednesday, April 17, 2013

[Extended Events] What servers are connecting to my SQL Server 2012 box?

(code is complete, soup-to-nuts, but only runs on 2012; I'll modify it for 2008/R2 in another post.)

(update 2013/04/18 Jonathan Kehayias helpfully provided a way to do it by adding the existing_connection event - but there appears to be a bug with the histogram, and it doesn't return the right data.  Connect item if you want to vote on it: https://connect.microsoft.com/SQLServer/feedback/details/785042/extended-events-histogram-does-not-properly-save-existing-connection-results)


First of all, MANY thanks to Jonathon Kehayias for all the XE wisdom and code - I modified the snot out of his http://www.sqlskills.com/blogs/jonathan/tracking-sql-server-database-usage/ lock-tracking-using-a-histogram to build this...


Say I want to figure out what servers are connecting to my SQL Server.  This is something you'd traditionally either poll sysprocesses for periodically, or probably run a trace.  Both have issues, though, especially if they're busy servers.  So, how can we get that?  Extended Events.

The easiest way to do this would be using Extended Events - create a "bucketizer" (now called the histogram), and watch for new logins, saving the servername and incrementing a counter each time it happens.  As a bonus, we could then filter it - exclude particular applications, servers, etc (see the commented out code).  And, since it's a pretty basic XE, overhead is very low.  The one caveat is that you can only get one piece of information out - servername.  I'd LOVE to get the App Name & DB Name as well, but you can only get one piece of information at a time.  Downer.  : - (

One caveat: If you have servers that stay connected, and don't open new connections, you won't see them here.  The obvious exclusion, then, is replication, but maybe your app hangs on for a long time (we've seen that with third-party tools).  Easy answer for those is to use SP_WHOISACTIVE.

Any questions?


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?