Monday, April 4, 2011

Extended Events to Capture Errors;

Hi Extended Events were introduced in SQL Server 2008, I just started learning about it, Jonathan Kehayias has an excellent white paper on Extended Events White Paper.  He has also blogged about it extensively.
I have frequently encountered problem where user doesn't have permission to execute something or they have errors running some script. I used to start a trace to monitor for Errors and Warnings. I thought about doing it differently, Extended Events can be used to capture permission denied errors, syntax errors and login failures etc. I have a small script to demonstrate that.

-- Create an Event session named CaptureErrors we are looking for errors between 10 and 20 in severity. I am using a file target. Also capturing sql_text, along with the database id, host computer etc.

Jonathan had mentioned about using max dispatch latency of 1 second ,  since it could impact the dispatcher pool and  it should be used  for demonstration purposes only.

CREATE EVENT SESSION CaptureErrors

ON SERVER
   ADD EVENT sqlserver.error_reported
   (ACTION (sqlserver.sql_text,sqlserver.database_id,sqlserver.client_hostname
   ,sqlserver.username,sqlserver.nt_username,sqlserver.tsql_stack)
     WHERE severity>=10 and severity<20/*anything over20 is captured by System Health Event*/ )
   ADD TARGET package0.asynchronous_file_target
  (SET FILENAME = N'C:\Program Files\Microsoft SQL Server\MSSQL11.V1\MSSQL\Log\CaptureErrors.xel'
  , METADATAFILE = N'C:\Program Files\Microsoft SQL Server\MSSQL11.V1\MSSQL\Log\CaptureErrors.xem')
       WITH (max_dispatch_latency = 1 seconds);
GO
ALTER EVENT SESSION CaptureErrors ON SERVER

STATE = START
GO

--Once its started we could execute some scripts to generate errors

SELECT * from  databases
go
SELECT  from test1
GO

--We could then Query the file target and get the error messages.


IF OBJECT_ID('tempdb..#ErrorData') IS NOT NULL
       DROP TABLE #ErrorData
CREATE TABLE #ErrorData
(event_data xml)

INSERT INTO #ErrorData (event_data)
SELECT  CAST(event_data as XML) FROM sys.fn_xe_file_target_read_file
     ('C:\Program Files\Microsoft SQL Server\MSSQL11.V1\MSSQL\Log\CaptureErrors*.xel'
, 'C:\Program Files\Microsoft SQL Server\MSSQL11.V1\MSSQL\Log\CaptureErrors*.xem', NULL, NULL);

SELECT
       event_data.value('(event/@name)[1]', 'varchar(50)') AS event_name,
   event_data.value('(event/@package)[1]', 'varchar(50)') AS package_name,
   event_data.value('(event/@id)[1]', 'varchar(50)') AS ID,
   event_data.value('(event/@version)[1]', 'varchar(50)') AS Version,
   DATEADD(hh,DATEDIFF(hh, GETUTCDATE(), CURRENT_TIMESTAMP),
           event_data.value('(event/@timestamp)[1]', 'datetime2')) AS [timestamp],
   event_data.value('(event/data[@name="error"]/value)[1]', 'int') as ErrorNumber,
   event_data.value('(event/data[@name="severity"]/value)[1]', 'smallint')  AS Severity,
   event_data.value('(event/data[@name="state"]/value)[1]', 'tinyint')  AS [State],
   event_data.value('(event/data[@name="user_defined"]/value)[1]', 'nvarchar(100)') as User_Defined,
   event_data.value('(event/data[@name="message"]/value)[1]', 'nvarchar(250)') as [Message],
   event_data.value('(event/action[@name="sql_text"]/value)[1]', 'nvarchar(4000)') as sql_text,
   event_data.value('(event/action[@name="database_id"]/value)[1]', 'int') as DatabaseID,
   event_data.value('(event/action[@name="client_hostname"]/value)[1]', 'nvarchar(4000)') as client_hostname,
   event_data.value('(event/action[@name="nt_username"]/value)[1]', 'nvarchar(4000)') as nt_username,
   event_data.value('(event/action[@name="username"]/value)[1]', 'nvarchar(4000)') as username,
   event_data.value('(event/action[@name="tsql_stack"]/value)[1]', 'nvarchar(4000)') as tsql_stack
FROM #ErrorData
ORDER BY [timestamp]

Below is the results from the above query, I ran aT-SQL commands that generated Syntax error  and another was a missing object, Then I had two login failure error messages. Extended Events Captured those information as we can see.




References:
http://sqlblog.com/blogs/jonathan_kehayias/archive/2010/12/15/an-xevent-a-day-15-of-31-tracking-ghost-cleanup.aspx
http://www.sqlskills.com/BLOGS/PAUL/category/Extended-Events.aspx





1 comment:

  1. Hey Jay,

    The impact of MAX_DISPATCH_LATENCY would be seen only in scenarios where your events are firing incredibly fast, which wouldn't be the likely case for the Error Events, or at least I would really hope your database code doesn't have errors that often. That said, since you currently have to poll the targets for new data and there is no streaming provider for Extended Events, there isn't a really good reason to set a low value for the dispatch latency unless you are actually polling the session that rapidly for new events, a task that would generally require a multi-threaded application to handle the work of shredding XML asynchronously through queuing while reading the event data from SQL Server. An example of where this is done can be found in the TargetDataViewer classes of the SSMS Addin I wrote on Codeplex.

    Cheers!

    ReplyDelete