2

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.

  • 2
    It's possible, but there are all sorts (ha!) of other reasons your query might identify a procedure. It's hard to trace sort warnings back to the source statement after the event, much better to collect information as they occur. If you think it is daft the default trace contains Sort Warnings with no T-SQL source, you're not alone. – Paul White says GoFundMonica May 23 '14 at 10:42
  • How likely is it that these sort warnings are what's causing my timeouts? The reason I'm asking is because my time allotted for troubleshooting this issue is very limited. – Reaces May 23 '14 at 10:50
2

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.

  • I'm afraid the count gives 0 for every SP on the database. I guess I'm looking at the wrong tree. Time to head back in the forest. – Reaces May 23 '14 at 10:12
  • Hmm...you appear to be right...Maybe they're not on the cached plans. I'd recommend running an Extended Event by following the link I posted. – Mark Sinkinson May 23 '14 at 10:18
  • 8
    Cached plans are always pre-execution (estimated) plans. Sort warnings are only present in post-execution (actual) plans. Collecting data using Extended Events or Event Notifications is indeed the way to go. – Paul White says GoFundMonica May 23 '14 at 10:37

Your Answer

By clicking “Post Your Answer”, you agree to our terms of service, privacy policy and cookie policy

Not the answer you're looking for? Browse other questions tagged or ask your own question.