Sort Warnings, finding out the query behind them

Question

I'm troubleshooting a SQL Server 2012 that has started timing out as of a few weeks ago.

The server is filled with thousands of sort warnings, at a rate of about 15 warnings per minute.

To get the sort warnings I used the following query:

DECLARE @log NVARCHAR(1000)

SELECT 
    @log = Substring(PATH, 1, Len(PATH) - Charindex('\', Reverse(PATH))) + '\log.trc'
FROM
    sys.traces
WHERE  
    id = 1

SELECT 
   g.TransactionID, c.name as category, e.name as event, 
   g.hostname as servername, g.databasename as using, 
   g.sessionloginname as login, g.starttime, g.textdata as query 
FROM  
   ::fn_trace_gettable(@log, 0) as g
inner join 
   sys.trace_events e on g.eventclass = e.trace_event_id 
inner join 
   sys.trace_categories as c on e.category_id = c.category_id
where 
   c.type not in ('0') 
order by 
   starttime desc

However the textdata column is always empty.

I'm almost certain that the sort warnings are originating from old stored procedures. However I can't find out the exact cause, as there are over 100 stored procedures being triggered every minute, how would I go about finding the query that's behind the warnings?

Update:

SELECT 
    p.name, p.object_id, p.create_date, p.modify_date, 
    s.last_elapsed_time, s.last_worker_time, 
    (s.last_elapsed_time - s.last_worker_time) as time_difference,  
    s.execution_count, last_execution_time 
FROM 
    SYS.dm_exec_procedure_stats as s
INNER JOIN 
    sys.procedures as p on p.object_id = s.object_id
WHERE 
    database_id = 11 AND s.last_worker_time < s.last_elapsed_time
ORDER BY 
    time_difference desc

Shows me that a few procedures (3) have last_elapsed_time of 200'000+ and worker time much lower. One stands out as being executed 15'000+ times, while having 400'000+ longer elapsed_time than worker_time. And this query does indeed sort on a rather large table.

Could someone tell me if what I'm looking at is a possible cause of the sort warnings, or if I'm going in circles.

Answer 1

You can tweak your query slightly to get a count of 'SpillToTempDb' i.e. Sort warnings, which would show you if any of the queries you're looking at could be an issue.

WITH 
XMLNAMESPACES (DEFAULT N'http://schemas.microsoft.com/sqlserver/2004/07/showplan')
SELECT 
p.name, 
p.object_id, 
p.create_date, 
p.modify_date, 
s.last_elapsed_time, 
s.last_worker_time, 
(s.last_elapsed_time - s.last_worker_time) as time_difference,  
s.execution_count, 
last_execution_time,
Query_Plan.value('count(/ShowPlanXML/BatchSequence/Batch/Statements/*/QueryPlan/Warnings/SpillToTempDb)', 'int') TempDbSpillWarnings
FROM SYS.dm_exec_procedure_stats as s
CROSS APPLY sys.dm_exec_query_plan(s.plan_handle) AS deqp
INNER JOIN sys.procedures as p on p.object_id = s.object_id
where database_id = 11 and s.last_worker_time < s.last_elapsed_time
order by time_difference DESC

Otherwise, since you are on SQL Server 2012, I would recommend running an Extended Event for an hour or so. There's a good guide on doing so half way down this tutorial.