This post is participating in Adam Machanic’s new invention and exciting blog party tradition in SQL Server community known as T-SQL Tuesday. Here is my second story for T-SQL Tuesday #002: A Puzzling Situation as I didn’t get to participate for the first one.
This particular issue happened to me last year and its worth sharing with the community. I was a database developer at that time and due to a change of hands on the deck last year, I was given access to our Datawarehouse server to manage and this particular server had some serious performance issues. The nightly data load job used to take almost 3 hours and has been failing at that time frequently. Being the one ready to take on challenging work, I decided to spend time to improve the performance of this 1 TB server and this server had only 8 GB of RAM.
The first thing I did was to look at the default trace (thanks to Jonathan Kehayias) and surprised to see few hundred sort warnings every day especially during the nightly job. For readers who doesn’t know about these, SQL server will try to use the memory to do the sorting initially but if there are only few free memory buffers left then this sort operation will spill to tempdb. SQL Server will raise ‘Sort Warnings’ event when this happens and it can take multiple passes to tempdb to get the sorted output. Every pass to tempdb is additional overhead and takes extra resources. Note that a query with out any Sort Warnings will perform better compared to single pass, query with single pass will perform better compared to multiple passes. I created some indexes after looking at the missing indexes, fixed some bad code and hoped the Sort Warnings might go away. When I looked at the default trace next day, I could see hundreds of those Sort Warnings staring back at me.
Here is code snippet to look at the Sort Warnings using the default trace and snippet is from Jonathan’s code.
DECLARE @filename VARCHAR(50)
SELECT @filename = CAST(value AS VARCHAR(50))
FROM fn_trace_getinfo(DEFAULT)
WHERE property = 2
AND value IS NOT NULL
--Check if you have any Sort Warnings
SELECT gt.HostName,
gt.ApplicationName,
gt.NTUserName,
gt.NTDomainName,
gt.LoginName,
gt.SPID,
gt.EventClass,
te.Name AS EventName,
gt.EventSubClass,
gt.TEXTData,
gt.StartTime,
gt.EndTime,
gt.ObjectName,
gt.DatabaseName,
gt.FileName
FROM [fn_trace_gettable](@fileName, DEFAULT) gt
JOIN sys.trace_events te ON gt.EventClass = te.trace_event_id
WHERE EventClass = 69
ORDER BY StartTime;
--Get a scale of this issue
SELECT DATEADD(dd,DATEDIFF(dd,0,gt.StartTime),0),
gt.EventSubClass,
COUNT(1) AS MeasureMe
FROM [fn_trace_gettable](@fileName, DEFAULT) gt
JOIN sys.trace_events te ON gt.EventClass = te.trace_event_id
WHERE EventClass = 69
GROUP BY DATEADD(dd,DATEDIFF(dd,0,gt.StartTime),0), gt.EventSubClass
ORDER BY DATEADD(dd,DATEDIFF(dd,0,gt.StartTime),0), gt.EventSubClass
I fired up profiler hoping to catch these Sort Warnings as they happen but surprised that TextData column can’t be selected for this event. Bummer! Look image above. Looking around the internetz, I found an interesting article by Solomon Rutzky for SSC using SQL Profiler, trigger, dbcc inputbuffer and temp tables. The setup was created and really hoped to find the root cause of hundreds of sort warnings. On that night, to my surprise it caught the offending procedure but it was pretty useless to me. This setup caught the top most calling SP but in my environment we had a nesting of stored procedure calls 5 levels deep. I had to modify the code snippet to utilize the SQL Server 2005 DMV’s as listed below and to my excitement that night I found the root cause of those hundreds of sort warnings. Its because of UPDATE STATISTICS job right before the nightly job.
USE [dba]
GO
SET ANSI_NULLS ON
GO
SET QUOTED_IDENTIFIER ON
GO
CREATE TRIGGER[dbo].[TraceTableExtraInfo1]
ON[dbo].[Trace_041409]
AFTER
INSERT
AS
BEGIN
SET NOCOUNT ON;
DECLARE@SQL VARCHAR(4000)
SELECT@SQL = 'select SUBSTRING(dest.text, (der.statement_start_offset/2)+1,
((CASE der.statement_end_offset
WHEN -1 THEN DATALENGTH(dest.text)
ELSE der.statement_end_offset
END - der.statement_start_offset)/2) + 1) AS statement_text
from sys.dm_exec_requests as der cross apply sys.dm_exec_sql_text (der.sql_handle) as dest
where session_id =
'+CONVERT(VARCHAR(10),ISNULL(ins.SPID,0)) +''
FROM inserted ins
CREATE TABLE#DBCCInfo (EventInfo NVARCHAR(4000))
INSERT INTO#DBCCInfo (EventInfo)
EXEC(@SQL)
UPDATE tt
SET tt.TEXTData =info.EventInfo
FROM dbo.[Trace_041409]e IN the tracel tt
INNER JOIN inserted ins
ON ins.RowNumber =tt.RowNumber
CROSS JOIN #DBCCInfo info
WHERE tt.TEXTData IS NULL
DROP TABLE#DBCCInfo
END
Here is the code snippet used by the UPDATE STATISTICS.
SELECT StatMan([SC0], [SB0000])
FROM (
SELECT TOP 100 PERCENT [SC0], step_direction([SC0]) OVER (
ORDER BY NULL) AS [SB0000]
FROM (
SELECT [cEndDateTime] AS [SC0]
FROM [dbo].[Tablename] WITH (READUNCOMMITTED,SAMPLE 5.949706e+001 PERCENT) ) AS _MS_UPDSTATS_TBL_HELPER
ORDER BY [SC0], [SB0000] ) AS _MS_UPDSTATS_TBL OPTION (MAXDOP 1)
UPDATE STATISTICS was using a proprietary STATMAN, STEP_DIRECTION T-SQL function along with an TOP 100 PERCENT with ORDER BY inside the subquery and this was leading to the hundreds of Sort Warnings. Until that time, I never knew that UPDATE STATISTICS can throw Sort Warnings. A connect item (Update statistics, top 100 percent and Sort warnings) was created for this and if you agree, vote for this item. I made few additional changes to improve the performance of the nightly job and also convinced my boss to add more RAM. For the past year the nightly job is taking 1 hour 20 minutes consistently and I got to sleep better at nights.
The above post is based on the blog post of mine posted last year.
Tracking & Resolving Sort Warnings in SQL Server
