Identifying failed queries with extended events

Back to some core SQL this week and one of my favourite features, extended events.

Introduced in SQL Server 2008 they are a big improvement on SQL profiler, in the amount of information that can be tracked (more) and the impact that they have on the system (less).

If you are still using profiler, please stop now! 🙂

One of the sessions that I have constantly running on SQL Server instances that I monitor is one to capture information on failed queries. You need to know what queries are failing on your production instances and why.

So let’s go through setting the session up, here’s the script to setup the extended event (remember to change the file paths for the filename and meta-data file!): –

CREATE EVENT SESSION [FailedQueries] ON SERVER 
ADD EVENT sqlserver.error_reported 
	(ACTION(sqlserver.client_app_name, sqlserver.client_hostname,  
		sqlserver.database_name, sqlserver.sql_text, sqlserver.username) 
	WHERE ([package0].[greater_than_int64]([severity], (10)))) 

ADD TARGET package0.event_file (SET 
	filename = N'C:\SQLServer\XEvents\FailedQueries.xel'
	,metadatafile = N'C:\SQLServer\XEvents\FailedQueries.xem'
	,max_file_size = (5)
	,max_rollover_files = (10))

WITH (STARTUP_STATE = ON)
GO

The new extended event can be viewed under Object Explorer > Management > Extended Events in SSMS: –

What this is going to do is create an extended event that will automatically startup when the SQL instance starts and capture all errors recorded that have a severity level greater than 10.

Full documentation on severity levels can be found here but levels 1 through 10 are really just information and you don’t need to worry about them.

I’ve also added in some extra information in the ACTION section (for bits and bobs that aren’t automatically included) and have set the maximum number of files that can be generated to 10, each with a max size of 5MB.

I’ve left pretty much everything else out for clarity but more details on the options that are available when creating sessions can be found here.

Let’s start the session up: –

ALTER EVENT SESSION [FailedQueries] ON SERVER 
	STATE = START;
GO

Now you can watch the queries be recorded live by right clicking in SSMS and selecting “Watch Live Data”…

…but I want to show you how to parse the events recorded in the file. Let’s test the event by running: –

SELECT 1/0;

Which will obviously fail!

So now we can parse the event, this requires a little XQuery but it’s not too bad (also, remember to change the filepath!): –

SELECT
	[XML Data],
	[XML Data].value('(/event[@name=''error_reported'']/@timestamp)[1]','DATETIME')				AS [Timestamp],
	[XML Data].value('(/event/action[@name=''database_name'']/value)[1]','varchar(max)')		AS [Database],
	[XML Data].value('(/event/data[@name=''message'']/value)[1]','varchar(max)')				AS [Message],
	[XML Data].value('(/event/action[@name=''sql_text'']/value)[1]','varchar(max)')				AS [Statement]
FROM
	(SELECT 
		OBJECT_NAME				 AS [Event], 
		CONVERT(XML, event_data) AS [XML Data]
	FROM 
		sys.fn_xe_file_target_read_file
	('C:\SQLServer\XEvents\FailedQueries*.xel',NULL,NULL,NULL)) as FailedQueries;
GO

So there we have the XML generated by the extended event and we’ve parsed it into readable columns!

Now with larger files XQuery can be heavy intense on resources so what I tend to do is copy the event’s files to my local machine before parsing; so just be wary when running.

As I said earlier I always have this event running on instances of SQL that I monitor. There really shouldn’t be any impact in doing so as (hopefully) there aren’t that many queries that fail in the instance. As ever though, test this thoroughly before going anywhere near production with it.

Thanks for reading!

Identifying Blocking via Extended Events

There are a number of ways that you can identify blocking that is occurring in your SQL instance. You can run the undocumented sp_who2 stored procedure but that will only give you the session that is being blocked. You could download the excellent sp_whoisactive, written by Adam Machanic, which will give you the session_id and the SQL script that is causing the blocking. However both of these methods will only show you blocking sessions when you run it (obviously). If you want to capture historical blocking information then another method is needed. If you suspect that blocking is occurring in your system, the best way to capture the information is to use Extended Events.

In order to do this, first enable the blocked process report:-

EXEC sp_configure 'Show Advanced Options', 1
RECONFIGURE

EXEC sp_configure 'blocked process threshold (s)', 1
RECONFIGURE

EXEC sp_configure 'Show Advanced Options', 0
RECONFIGURE

N.B. – I’ve set the threshold limit here to one second. Depending on your environment you may wish to change it.

Then create an extended event to capture the information from the report:-

CREATE EVENT SESSION [BlockedProcesses] ON SERVER 
    ADD EVENT sqlserver.blocked_process_report
    ADD TARGET package0.event_file(SET filename=N'C:\SQLServer\XEvents\BlockedProcesses\BlockedProcesses.xel',max_file_size=(128))
WITH (STARTUP_STATE=OFF)
GO

N.B. – Don’t forget to change the file path.

Then start the session:-

ALTER EVENT SESSION [BlockedProcesses] ON SERVER
    STATE = START;

Now that the session is running you can query it:-

SELECT
 [XML DATA] AS [Raw XML],
 [XML Data].value('(/event[@name=''blocked_process_report'']/@timestamp)[1]','DATETIME') AS [TimeStamp],
 [XML Data].value('(/event/data[@name=''database_name'']/value)[1]','SYSNAME') AS [Database Name],
 [XML Data].value('(/event/action[@name=''username'']/value)[1]','SYSNAME') AS [Username],
 [XML Data].value('(/event/data[@name=''transaction_id'']/value)[1]','BIGINT') AS [Transaction ID],
 [XML Data].value('(/event/data[@name=''lock_mode'']/text)[1]','SYSNAME') AS [Lock Mode],
 [XML Data].value('(/event/data[@name=''duration'']/value)[1]','BIGINT')/1024 AS [Duration (ms)],
 [XML Data].value('(/event/data[@name=''blocked_process'']/value/blocked-process-report/blocked-process/process/inputbuf)[1]','SYSNAME') AS [Blocked Query],
 [XML Data].value('(/event/data[@name=''blocked_process'']/value/blocked-process-report/blocked-process/process/@waitresource)[1]','SYSNAME') AS [Wait Resource], 
 [XML Data].value('(/event/data[@name=''blocked_process'']/value/blocked-process-report/blocking-process/process/inputbuf)[1]','SYSNAME') AS [Blocking Query]
FROM
    (SELECT OBJECT_NAME 			  AS [Event], 
		  CONVERT(XML, event_data) AS [XML Data]
	FROM 
	   sys.fn_xe_file_target_read_file('C:\SQLServer\XEvents\BlockedProcesses\BlockedProcesses*.xel',NULL,NULL,NULL)) AS v
ORDER BY [XML Data].value('(/event[@name=''blocked_process_report'']/@timestamp)[1]','DATETIME') DESC

EDIT:- It’s been pointed out in the comments by Jason that the value for username will return as NULL because no action was defined for this value in the CREATE EVENT script. Adding the following piece of code will allow the username to be returned:-

ADD EVENT sqlserver.blocked_process_report(
Action (sqlserver.Username))

This piece of code will output the time of the block, the blocked query, the blocking query, the duration of the block and the resource that the blocked query is waiting on. I’ll run through a quick example now to show what information is retrieved when a block is recorded. So first I’ll create a demo database with one table (I have already run the setup scripts above):-

USE [master];
GO
 
CREATE DATABASE [BlockingExample];
GO
 
USE [BlockingExample];
GO
 
CREATE TABLE dbo.[BlockedTable]
(RecordID INT IDENTITY(1,1) PRIMARY KEY,
 ColA SYSNAME);
 
INSERT INTO dbo.BlockedTable
(ColA)
VALUES
('Blocking TEST');
GO

Then I’ll open two sessions, the first will be an update in a transaction that I’ll leave open (my blocker):-

USE [BlockingExample];
GO
 
BEGIN TRAN
 
UPDATE dbo.[BlockedTable]
SET ColA = 'BlockingTEST1';

The second will be a simple SELECT against the table (my blocked query):-

USE [BlockingExample];
GO

SELECT * FROM dbo.BlockedTable;

I’ll run this for a while, cancel it and commit the first query. Then I queried the extended event, here’s the results:- BlockedProcessScreenShot As you can see, The SELECT is showing up as the blocked query and the update as the blocker. But we’ve also got the resource the SELECT is waiting on:- KEY: 14:72057594039042048 (8194443284a0) Using this information we can identify the exact row in the table. The 14 is the database_id:-

SELECT name from sys.databases WHERE database_id = 14

This gives the name of the test database “BlockingExample”. Next 72057594039042048 is the hobt_id of the table, we can get the table name by running:-

SELECT o.name
FROM sys.objects o
INNER JOIN sys.partitions p ON o.object_id = p.object_id
WHERE p.hobt_id = 72057594039042048

This outputs the name of the test table “Blocked Table”. Finally we can use (8194443284a0) to identify the exact row in the table by running:-

SELECT *
FROM dbo.BlockedTable
WHERE %%LOCKRES%% = '(8194443284a0)'

This will output the test record that was inserted and then locked by the UPDATE statement. A very contrived example, I know, but it does show how verbose Extended Events are when capturing blocking. Not only can we identity the blocker and blockee but the exact record that the blockee was waiting on.

Video – Identifying large queries using Extended Events

A couple of weeks ago I was contacted by Webucator (an online training company) asking if they could use my blog post “Identifying Large Queries using Extended Events” for a video training session in their free series called SQL Server Solutions from the Web.

The main reason I write this blog is to give back to the SQL Server community, so I was more than happy for Webucator to make this video. I hope it’s of benefit to someone out there.

The video’s great. The instructor, Bruce Gordon, goes through my post explaining what each piece of code does and then shows how to use the GUI (introduced in SQL Server 2012) to re-configure an existing Extended Events session.

Here’s the video:-

Webucator provide many more SQL Server training videos here

Identifying large queries using Extended Events

Following on from my last blog post I now want to run through how to identify large queries using Extended Events.

Extended Events were introduced in SQL Server 2008 and allow monitoring to be run against a server with a lower performance impact than profiler sessions and server side traces.

There’s now a nice GUI in SQL Server 2012 in which you can setup your Extended Event session but I always like to start with creating a session using T-SQL:-

USE [master];
GO

CREATE EVENT SESSION [QueriesWith200kReads] ON SERVER 
ADD EVENT sqlserver.sql_batch_completed(
    ACTION(sqlserver.client_hostname,sqlserver.database_name,sqlserver.session_id,sqlserver.sql_text,sqlserver.tsql_stack,sqlserver.username)
    WHERE ([logical_reads]>200000))
ADD TARGET package0.event_file(SET filename=N'C:\SQLServer\XEvents\QueriesWith200kReads.xel')
GO

The script above will capture all SQL batches executed on the server that perform over 200,000 reads. I’ve set the target as a .XEL file and have defined what information to capture.

The session can then be started:-

ALTER EVENT SESSION [QueriesWith200kReads]
ON SERVER
STATE = START;
GO

While the session is running, the following can be executed to see how many queries have been captured:-

SELECT COUNT(*)
FROM sys.fn_xe_file_target_read_file
 ('C:\SQLServer\XEvents\QueriesWith200kReads*.xel',NULL,NULL,NULL);
GO

To query the data, XQUERY can be used. The below script grabs all the data from the session in a CTE and then combines it to give an overall view so that we can see which queries are being executed the most and are causing the most pain!

WITH CTE_ExecutedSQLStatements AS
(SELECT
	[XML Data],
	[XML Data].value('(/event[@name=''sql_statement_completed'']/@timestamp)[1]','DATETIME')	AS [Time],
	[XML Data].value('(/event/data[@name=''duration'']/value)[1]','int')						AS [Duration],
	[XML Data].value('(/event/data[@name=''cpu_time'']/value)[1]','int')						AS [CPU],
	[XML Data].value('(/event/data[@name=''logical_reads'']/value)[1]','int')					AS [logical_reads],
	[XML Data].value('(/event/data[@name=''physical_reads'']/value)[1]','int')					AS [physical_reads],
	[XML Data].value('(/event/action[@name=''sql_text'']/value)[1]','varchar(max)')				AS [SQL Statement]
FROM
	(SELECT 
		OBJECT_NAME				 AS [Event], 
		CONVERT(XML, event_data) AS [XML Data]
	FROM 
		sys.fn_xe_file_target_read_file
	('C:\SQLServer\XEvents\QueriesWith200kReads*.xel',NULL,NULL,NULL)) as v)

SELECT
	[SQL Statement]		AS [SQL Statement],
	SUM(Duration)		AS [Total Duration],
	SUM(CPU)			AS [Total CPU],
	SUM(Logical_Reads)	AS [Total Logical Reads],
	SUM(Physical_Reads) AS [Total Physical Reads]
FROM
	CTE_ExecutedSQLStatements
GROUP BY
	[SQL Statement]
ORDER BY
	[Total Logical Reads] DESC
GO

But what if we want to change the session? In SQL Server 2012 a GUI was introduced so sessions can be setup and changed easily.

At the moment, the session picks up queries that are performing over 200,000 logical reads. What if we wanted to also include any queries that are performing a large amount of physical reads?

In order to do this, in Object Explorer go to Management > Extended Events > Sessions.

XEvents Blog - Pic 1

Right click the session and then go to properties.

XEvents Blog - Pic 2

Go to Events.

XEvents Blog - Pic 3

Click configure.

XEvents Blog - Pic 4

Click the filter tab.

XEvents Blog - Pic 5

Select OR in the And/Or box and then select Physical Reads, Greater than (>) and 10000 in the adjacent boxes.

XEvents Blog - Pic 6

Then either click OK or Script. I always script out the changes that I have made so that I can re-create the session if needed:-

ALTER EVENT SESSION [QueriesWith200kReads] ON SERVER 
DROP EVENT sqlserver.sql_batch_completed

ALTER EVENT SESSION [QueriesWith200kReads] ON SERVER 
ADD EVENT sqlserver.sql_batch_completed(
    ACTION(sqlserver.client_hostname,sqlserver.database_name,sqlserver.session_id,sqlserver.sql_text,sqlserver.tsql_stack,sqlserver.username)
    WHERE (([package0].[greater_than_uint64]([logical_reads],(200000))) OR ([physical_reads]>(10000))))
GO

Finally there is also the ability to watch events as they are captured (think profiler session with a lot less impact).

Again in Object Explorer go to Management > Extended Events > Sessions.
Right click the session and select Watch Live Data.

XEvents Blog - Pic 7

Columns can be added by right clicking the existing columns and selecting Choose Columns.

And there you have it, how to setup and alter an Extended Event session using scripts and/or the GUI.