Archive

Archive for the ‘Performance’ Category

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

07/12/2011 Leave a comment

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. 🙂

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

05/12/2011 1 comment

Sort warnings events will rise when sort operation is performed in a query and it doesn’t fit into memory. In this case, SQL Server needs to spill the sort operation into tempdb which can result in a very slow physical operation especially if multiple passes to tempdb is needed for sorting the data. Ideally, there shouldn’t be any sort warnings on a server.

How to detect Sort Warnings in SQL Server 2008 (R2)?

In SQL Server 2008 (R2), sort warning event can be detected using SQL Profiler. SQL Server default trace has this event included by default. But using Sort Warning event in SQL Profiler we can’t capture what statements are causing these warnings because TextData column isn’t available.  Solomon Rutzky presented a way of finding statements by using profiler trace, trigger and DBCC INPUTBUFFER.

SQL Server 2008 (R2) doesn’t provide an event through Extended Events to track sort warnings. In SQL Server 2012 this will change.

How to detect Sort Warnings in SQL Server 2012 RC0?

In SQL Server 2012 RC0, the number of event has expanded to 616 and one of these new events is sort_warning event. Extended Events Sort_warning event can be used to detect what statements are causing sort warnings.  I will show how to use sort_warning event to detect sort warnings in database. Let’s create a new database with a simple table and stored procedures for testing.

-- Create TestSortWarnings database
CREATE DATABASE TestSortWarnings
GO
USE TestSortWarnings
GO
-- Create TestTable
CREATE TABLE dbo.TestTable (Col1 int IDENTITY(1,1), Col2 varchar(8000))
GO
-- Insert data into table
INSERT INTO dbo.TestTable (Col2)
SELECT REPLICATE('A','8000')
GO 200

CREATE PROCEDURE dbo.Test
AS
SET NOCOUNT ON

-- Declare table variable
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

CREATE PROCEDURE dbo.Test1
AS
SET NOCOUNT ON

-- Declare table variable
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
OPTION (RECOMPILE)

-- Example with DINSTINCT
SELECT DISTINCT Col2 FROM @T1
-- Example with GROUP BY
SELECT Col2, COUNT(*) FROM @T1
GROUP BY Col2

Table TestTable has 2 columns, no indexes and has 200 rows. Two stored procedures will generate sort warnings during execution. I will use this database, table and stored procedures in all my examples.

Detecting Sort Warnings with Extended Events

SQL Server 2012 management studio (SSMS) has UI for creating and managing Extended Events and it will be much easier to use it. Great thing is that SSMS includes an event session data viewer for all targets except the ETW file target. If you want to learn more about it you can read a post “Introducing the Extended Events User Interface” written by SQL Team. Post is focused on the mechanisms for creating event sessions and displaying event session data.

In this post I will use T-SQL but everything from this post can be done with UI. Next script will create event session SortWarning with ring_buffer target. It will capture sqlserver.sort_warning event with sqlserver.sql_text action. 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.


CREATE EVENT SESSION SortWarning ON SERVER
ADD EVENT sqlserver.sort_warning(
  ACTION(sqlserver.sql_text)
  WHERE (sqlserver.database_id=(7))) -- Replace database_id
ADD TARGET package0.ring_buffer
GO

-- Start the Event Session
ALTER EVENT SESSION SortWarning
ON SERVER
STATE=START
GO

I will use prepared test data to simulate sort warnings. I will also include Actual Execution Plan to demonstrate new warnings information in it.

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

If we look at Active Execution Plan we can see a warning on sort operator.

Let’s execute the stored procedure Test:

 EXEC dbo.Test
GO 

Let’s retrieve the event data from the event session target:

DECLARE @XEvent XML
SELECT @XEvent = CAST(target_data AS XML)
FROM sys.dm_xe_sessions s
INNER JOIN sys.dm_xe_session_targets t
  ON s.address = t.event_session_address
WHERE s.name = 'SortWarning'
AND t.target_name = 'ring_buffer'

SELECT
  event_data.value('(./@name)[1]', 'varchar(20)') AS event_name,
  DATEADD(hh, DATEDIFF(hh, GETUTCDATE(), CURRENT_TIMESTAMP), event_data.value('(./@timestamp)[1]', 'datetime')) AS timestamp,
  event_data.value('(./data[@name="sort_warning_type"]/text)[1]', 'varchar(20)') AS sort_warning_type,
  event_data.value('(./action[@name="sql_text"]/value)[1]', 'varchar(max)') AS sql_text
FROM @XEvent.nodes('RingBufferTarget[1]/event') XE(event_data)
 

Results:

Sort_warning event is raised 2 times. We see that singe pass over the data are required to sort the data and statements which caused spill to tempdb.  Let’s now execute stored procedure dbo.Test1 (with included Actual Execution plan).

 EXEC dbo.Test1
GO 

If we look at Actual Execution Plan we can see that stored procedure Test1 caused 2 sort warnings. (1) Second statement in stored procedure with ORDER BY didn’t cause sort warnings because of OPTION (RECOMPILE). Statements with DISTINCT (2) and GROUP BY (3) caused sort warnings.

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

As we can see, by capturing only sqlserver.sort_warning event and sqlserver.sql_text action in event session we have information about the statement sent from a client to an SQL Server. Sometimes, that can be enough, but in some situations we need more information. If we have a stored procedure, which can be nested for example, with more statements that use sort operator (like Test1 stored procedure from our example), we will not know exactly which statements inside a stored procedure are causing sort warning events.

My next post will show how we can track sort warnings to the statement level inside a stored procedure.

 

SQL Server: Simple Parameterization

31/10/2011 Leave a comment

Simple parameterization is SQL Server feature which allow the optimizer to parameterize submitted queries. If submitted query has no parameters and has constant values plugged in, the optimizer can choose to treat constant values as parameters and automatically create parameterized query and execution plan for it. Simple parameterization is on by default and it’s designed to reduce cost of generating execution plans. SQL Server uses a simple parameterization for a relatively small set of queries where query plan doesn’t depend on particular constant values.
To see how simple parameterization works I will use AdventureWorks database. Let’s run some simple query and see what is written in SQL Server’s plan cache.

DBCC FREEPROCCACHE
GO
SELECT *
FROM Production.TransactionHistory
WHERE TransactionID = 213429
GO
SELECT cp.objtype,
cp.usecounts,
cp.size_in_bytes,
cp.plan_handle,
st.text,
qp.query_plan
FROM sys.dm_exec_cached_plans cp
CROSS APPLY sys.dm_exec_sql_text (cp.plan_handle) st
CROSS APPLY sys.dm_exec_query_plan (cp.plan_handle) qp
WHERE st.text LIKE '%TransactionHistory%'
AND st.text NOT LIKE '%sys.dm_exec_cached_plans%'
GO

Here are the results from the plan cache query:

We can see that SQL Server created two entries in the cache. The first entry is submitted query with constant value and it’s cached as objtype adhoc. It is a shell query and it doesn’t contain execution plan. A shell query contains only the exact adhoc batch text and pointer to the parameterized (prepared) plan. The second entry is parameterized query and has objtype of prepared. Prepared query contains compiled execution plan and query text with a parameter in place of a constant value. We can also see that shell query use 16KB of cache while prepared plan use 32KB. If we open a query_plan of the shell query we can see that shell query contains only pointer to the prepared plan. From (1) we can see which parameterized plan is used with parameterized query text and in (2) we can see which statement is submitted.

Let’s run same type of the query but with different constant value (213430). If we observe SELECT operator in the actual execution plan of the query we can tell that query is parameterized.

(1) In “Parameter List” we can see “Parameter Compiled Value” and “Parameter Runtime Value”. (2) Shows us parameterized text and (3) gives us hash value of the query plan. We can use QueryPlanHash value to return query plan and execution count of the parameterized query.

SELECT st.text, qs.execution_count, qp.query_plan
FROM sys.dm_exec_query_stats qs
CROSS APPLY sys.dm_exec_sql_text (qs.plan_handle) st
CROSS APPLY sys.dm_exec_query_plan (qs.plan_handle) qp
WHERE qs.query_plan_hash = 0xAFB37EEDFFA28FE3

If we look at results of plan cache query again, we can see that the second shell query is created with the exact text of the second query and it points to a parameterized plan.

Why shell query is cached when it only points to parameterized query? It’s cached only to make it easier to find parameterized query if the exact same query with the same constant is re-executed later.

Now, I will show one interesting behavior of simple parameterization. Let’s run same type of the query but with constant value of 5. Here are the results from the plan cache query:

Two new entries are created. (1) One shell query and one (2) prepared but with parameter data type of tinyint. It’s strange that the optimizer created a new prepared query with tinyint data type parameter when there is a cached plan with int parameter value. It seems that the optimizer, during simple parameterization, use parameter with the lowest possible data type for the specified constant value of number data type. If we execute the query with varchar or nvarchar constant value, data type varchar(8000) and nvarchar(4000) is used as parameter.

As I mentioned at the begging of the post, relatively small set of queries will be simple parameterized. Only simple queries whose plan doesn’t depend on constant value will be considered “safe” for simple parameterization and will be cached. Also, there are a lot of statement types which SQL Server will not even attempt to auto-parameterize.  For complete list of these statement types you can check Apendix A in the article Plan Caching in SQL Server 2008.

Let’s take a look at these simple queries.

SELECT TransactionID, ProductID
FROM Production.TransactionHistory
WHERE ProductID = 725
GO
SELECT *
FROM Production.TransactionHistory
WHERE ProductID = 725
GO

If we execute those 2 queries and check results from plan cache query we can see that first query is parameterized and second one isn’t. Why?

For the first query, Query Optimizer thinks that nonclustered index seek is the best option for the query even when constant value change, because only columns we need are contained in the nonclustered index (clustered index is created on TransactionID column).
The second query is different, we want all columns from the table and a nonclustered index seek and key lookup might be a good choice when only a few rows are returned, but it might be a terrible choice when many rows are returned.  If we look at query_plan from the second query we can see that query is parameterized. It seems that query went through auto-parameterization process but query optimizer decided that it is “unsafe” and parameterized query isn’t cached.

Conclusion:

SQL server will simple parameterize some simple queries whose plan doesn’t depend on different constant values. During simple parameterization, if the optimizer decide that parameterized query is “safe”, two entries are written to the plan cache: shell query and prepared query. Shell query doesn’t contain full plan, it only point to parameterized plan which contain full execution plan for the query. Shell and parameterized queries are cached to reduce cost of generating execution plans. If we run a lot of adhoc queries with different constant value, more parameterized queries for the same type of query but with different parameter data type and large number of shell queries will be written to the plan cache.

UPDATE STATISTICS: How to cheat the optimizer

10/10/2011 Leave a comment

Did you ever need to see what execution plan will optimizer choose for your query on large set of data but you have a really small test database? Or you are testing your notification system for sort warning, for example, and you need to force query optimizer to think that tables used in a query are smaller? If your answer is yes, then keep reading.

Statistics is very important to the query optimizer for generating execution plans and it’s very important that statistics is up to date in a production database. To update statistics we use UPDATE STATISTICS statement. If you read BOL page for update statistics you can see that statement has some undocumented options. We can use these undocumented options, ROWCOUNT and PAGECOUNT, to cheat the optimizer. In the SQL Server Query Optimization Team blog,  we can read that ROWCOUNT and PAGECOUNT alter the internal metadata of the specified table or index by overriding the counters containing the row and page counts of the object.

In the next example, I will show how to use ROWCOUNT and PAGECOUNT options and how to cheat the optimizer. You will see that internal metadata for the table are changed and that statistics isn’t updated. Never use this in production database.

To see how it works I will use Sales.SalesOrderDetail table in AdventureWorks2008R2 database.
First, let us see statistics for table’s primary key and information’s about rows and pages in the table from sys.partitions and sys.dm_db_partition_stats.

DBCC SHOW_STATISTICS ('Sales.SalesOrderDetail',PK_SalesOrderDetail_SalesOrderID_SalesOrderDetailID);

SELECT * FROM sys.partitions
WHERE object_id = object_id('Sales.SalesOrderDetail')

SELECT * FROM sys.dm_db_partition_stats
WHERE object_id = object_id('Sales.SalesOrderDetail')

Results:

DBCC SHOW_STATISTICS tell us (1) that Aug 2 2010 is the last time when statistics was updated and that table has 121.317 rows. Sys.partition (2) also tells us that table has 121.317 rows. sys.dm_db_partition_stats (3) shows us that 1.234 pages are used for storing in-row data.

Now, let’s UPDATE STATISTICS with ROWCOUNT and PAGECOUNT options. I set 500.000 rows and 10.000 pages but you can set any other value.

UPDATE STATISTICS Sales.SalesOrderDetail
WITH ROWCOUNT = 500000,PAGECOUNT = 10000

After we updated statistics with ROWCOUNT and PAGECOUNT option let us see again what is written in statistics and in sys.partitions and sys.dm_db_partition_stats.

From (1) we can see that statistics isn’t updated. From (2) we can see that sys.partition has information that table has 500.000 rows and sys.dm_db_partition_stats thinks that table occupies 10.000 pages (3). These values are used by query optimizer during query processing.
Let’s run a simple query on Sales.SalesOrderDetail table and look at actual execution plan of the query.

SELECT SalesOrderID
FROM Sales.SalesOrderDetail

Query is very simple. We want all SalesOrderID from the table. We can see that (1) actual number of rows is 121.371 but query optimizer thought (2) that there are 500.000 rows in the table.

Using ROWCOUNT and PAGECOUNT options allow us to cheat the query optimizer and to easily see what kind of query plan will be generated on large amount of data.  You can also specify smaller number of rows and pages to simulate a sort warning for example.

Categories: Performance, SQL Server

SQL Server Denali: New warnings in Actual Execution Plan

29/09/2011 Leave a comment

I’ve played with SQL Server Denali and found some new features and improvements in Query Execution plan. My intention was to test Extended Events and new events: sort_warning and hash_warnig. In SQL Server 2008R2, we can create SQL Trace to capture sort and hash warnings but there is no easy way to find out which statement cause it. I hoped that with new XEvent in Denali we can do that easily.
I reduced maximum server memory for SQL Server, ran some queries with ORDER BY and here is the Actual Execution Plan for one query.

Do you see something new? There is a warning on Sort operator (1) and on SELECT (2).
If we look at the Sort operator and SELECT we can see more information about warnings.

In Denali we see Sort warnings in query execution plan. It seems that some waits are also visible. Is the MemoryGrant only wait type that will appears in query plan?
I don’t know what kinds of warnings are included in Denali actual execution query plan but I think that these two warnings are not the only one.

Categories: Denali, Performance