Home > Database Administration, Extended Events, Performance, SQL Server 2012 > SQL Server 2012: Detecting Sort Warnings with Extended Events (sort_warning event) – Part 2

SQL Server 2012: Detecting Sort Warnings with Extended Events (sort_warning event) – Part 2

In my last post, SQL Server 2012: Detecting Sort Warnings with Extended Events (sort_warning event) I showed how to use sort_warning event with sql_text action to detect sort warnings in database with statements sent to SQL server instance. We also saw that using sql_text action we know what stored procedure or batch are causing sort warnings. But sometimes that isn’t enough.

If we have a stored procedure or a batch with more statements that use sort operator we would like to know the information about the exact statement inside stored procedure or batch that caused sort_warning event. In SQL Server 2012 that can be achieved using tsql_stack or tsql_frame actions. Action tsql_stack is available in SQL Server 2008 (R2) while tsql_frame action is new in SQL Server 2012.

Below is description for tsql_stack and tsql_frame actions from metadata DMV:

In this post I will use tsql_frame action. To run all examples from this post we need TestSortWarnings database I used in my last post. This time I will create Extended Events session SortWarning with event_file target and it will capture sqlserver.sort_warning event with sqlserver.sql_text and sqlserver.tsql_frame actions. Event session is configured with a predicate on the sqlserver.database_id to track sort warnings only on TestSortWarnings database. Before you execute the script, you need to replace a value for database_id with a value returned by SELECT DB_ID(‘TestSortWarnings’) statement. Next script will create and start Event session SortWarning.

IF EXISTS(SELECT * FROM sys.server_event_sessions WHERE name='SortWarning')
DROP EVENT SESSION [MultipleDataFiles] ON SERVER;
-- Create Event Session SortWarning
CREATE EVENT SESSION SortWarning ON SERVER
ADD EVENT sqlserver.sort_warning(
ACTION(sqlserver.sql_text,sqlserver.tsql_frame)
WHERE (sqlserver.database_id=(7))) -- replace database_id
ADD TARGET package0.event_file(SET filename = N'C:\Log\SortWarning.xel',max_file_size=(100))
WITH (MAX_MEMORY=4096 KB,EVENT_RETENTION_MODE=ALLOW_SINGLE_EVENT_LOSS,MAX_DISPATCH_LATENCY=30 SECONDS)
GO
-- Start the Event Session
ALTER EVENT SESSION SortWarning
ON SERVER
STATE=START
GO

With the event session created and started we can run next script which will generate sort warning event.

USE TestSortWarnings
GO
DECLARE @T1 TABLE (Col1 int, Col2 varchar(8000))
-- Insert data to table variable
INSERT INTO @T1 SELECT * FROM dbo.TestTable
-- Return data sorted on Col2 column
SELECT * FROM @T1
ORDER BY Col2 ASC
GO

Let’s read the data from the extended events log file.

SELECT CAST(event_data AS XML) AS event_data
FROM sys.fn_xe_file_target_read_file('C:\Log\SortWarning*.xel',null,null,null)

Here is the result:

Sort_warning_type and sql_text are collected (1) and we see information collected with tsq_frame action (2). We can use sql_handle and offset information (offsetStart and offsetEnd) from tsql_frame action element and sys.dm_exec_sql_text DMF to return the specific statement which caused sort_warning. Here is the script to retrieve data we need:

SELECT
x.object_name AS event_name,
DATEADD(hh, DATEDIFF(hh, GETUTCDATE(), CURRENT_TIMESTAMP), vent_data.value('(event/@timestamp)[1]', 'datetime')) AS timestamp,
event_data.value('(event/data[@name="sort_warning_type"]/text)[1]', 'varchar(20)') AS sort_warning_type,
event_data.value('(event/action[@name="sql_text"]/value)[1]', 'varchar(max)') AS sql_text,
frame_data.value('./@level','int') AS frame_level,
OBJECT_NAME(st.objectid, st.dbid) AS objectname,
SUBSTRING(st.text, (frame_data.value('./@offsetStart','int')/2)+1,
((CASE frame_data.value('./@offsetEnd','int')
WHEN -1 THEN DATALENGTH(st.text)
ELSE frame_data.value('./@offsetEnd','int')
END - frame_data.value('./@offsetStart','int'))/2) + 1) AS sort_warning_statement
FROM (SELECT object_name, CAST(event_data AS XML) AS event_data
FROM sys.fn_xe_file_target_read_file('C:\Log\SortWarning*.xel',null,null,null)) x
CROSS APPLY x.event_data.nodes('event/action[@name="tsql_frame"]/value/frame') Frame(frame_data)
OUTER APPLY sys.dm_exec_sql_text(CONVERT(varbinary(max), frame_data.value('./@handle','varchar(max)'),1)) st

The results:

From the result we can see that frame_level for batch is 0 and objectname is NULL. Sort_warning_statement column shows us what specific statement from the batch is causing sort warning while sql_text column returns complete batch sent to a SQL server instance. It gives us all information about sort warnings to the statement level.

Now let’s execute 2 stored procedures dbo.Test and dbo.Test1.

EXEC dbo.test
GO
EXEC dbo.test1
GO

If we retrieve the event data from the event session target again we will see 3 new records.

The output from event_file target:

We see that frame_level for stored procedure is 1 and we have the name of stored procedure and exact statement inside the stored procedure which caused sort warning. That’s all we need.

Let’s see what will happened if we encounter stored procedure nesting. In the next script I will create and execute stored procedure dbo.test2 which calls dbo.test1 procedure.

CREATE PROCEDURE dbo.Test2
AS
SET NOCOUNT ONEXEC dbo.Test1
GO

EXEC dbo.Test2
GO

The output from event_file target:

We can see that even with stored procedure nesting we have all necessary information about sort warnings event. Frame_level column is 2 and it tells us the nesting level for the stored procedure responsible for sort warning event.

I like how much information we can get with SQL Server 2012 extended events. Open-mouthed smile In this post I tried to show how easily we can track sort warnings to the statement level in SQL Server 2012.

I hope that you have learned something new. 🙂

Advertisements
  1. No comments yet.
  1. No trackbacks yet.

Leave a Reply

Fill in your details below or click an icon to log in:

WordPress.com Logo

You are commenting using your WordPress.com account. Log Out / Change )

Twitter picture

You are commenting using your Twitter account. Log Out / Change )

Facebook photo

You are commenting using your Facebook account. Log Out / Change )

Google+ photo

You are commenting using your Google+ account. Log Out / Change )

Connecting to %s

%d bloggers like this: