Along with sharing information about TFS, another purpose for this blog will be to share general tips and tricks that I come across while coding. I have really been trying to improve my SQL Server coding and debugging skills lately so expect SQL Server to be a common theme in these types of posts. Anyway, on to the content!
The issue that inspired this post happened a few days ago. A fellow developer had reported that one of my stored procedures seemed to “hang” while performing an operation so I needed to dig in to hopefully determine what the issue was. Since I wasn’t able to repro the issue with a simple case my next plan was to try to capture the exact command that caused the issue to reproduce using SQL Server Profiler and then replay that command in Sql Server Management Studio repeatedly with a bunch of different traces turned on.
While I was in the process of capturing the command using the profiling tool I noticed that the operation appeared to be in this “hanging” state that my colleague had reported. Since I had assumed that the hang was due to a bad SQL query plan or some other intermittent problem I was ecstatic that I was able to get it to reproduce. Then the panic set in. I realized that I didn’t have any statement level traces set up and was immediately worried that I wouldn’t gain any knowledge from this instance of a seemingly hard-to-reproduce issue.
So, with time on this repro running low, I did what every developer on my team with a SQL emergency would do, and that was to call my co-worker Chandru to help. Luckily, Chandru was able to save the day and determine what statement was causing the delay within the stored procedure before we lost the repro. So, for both your benefit and mine here is a recap of what I learned about how he was able to figure this out:
On to the contrived example!
In order to reproduce this issue at home, let’s use this example stored procedure:
CREATE PROCEDURE prc_LongRunningProcedure AS -- Declare some table DECLARE @table TABLE ( Value1 INT, Value2 INT ) INSERT @table (Value1, Value2) VALUES ( 1, 2 ) WAITFOR DELAY '05:00' SELECT * FROM @table RETURN 0 GO
After a quick inspection you will notice that the above procedure declares a temporary table, inserts some values, waits for 5 hours, and then returns the values from the table. While this example is incredibly contrived it will serve our purposes well. In an SSMS query window copy in the statement above and run it to create the stored procedure in a test database. Next, in another query window, run the following statement:
So now we have achieved the same issue that I was experiencing: a long running stored procedure that was stuck on an unknown statement. Okay, maybe you can guess what statement we are stuck on here but you know what I mean.
So, what next?
Luckily, SQL provides a number of different tables and functions that help track things that are of interest to someone trying to debug various issues. One of the most commonly useful tables is sys.dm_exec_requests which will report some details about the currently operating requests. Access those details using the following query:
SELECT * FROM sys.dm_exec_requests requests WHERE requests.session_id > 50 ORDER BY total_elapsed_time DESC
Note that we make sure to only select requests with a session_id above 50 because these represent “user” requests. Any request with a session_id at or below 50 represents a “system” request and those won’t be useful to us here. Running this statement in a new query editor window in SSMS yielded the following results for me. Note, you may see more or less results with different ids when you run this against your server.
Scrolling to the right it is fairly obvious for me which request is the long running one: the top row has a much higher total_elapsed_time value than the other entries. However, in a real world scenario, you may not be able to tell what stored procedure is running. In order to associate the currently running request with the stored procedure that is running we will have to call upon sys.dm_exec_sql_text:
SELECT requests.session_id, requests.status, requests.command, requests.statement_start_offset, requests.statement_end_offset, requests.total_elapsed_time, details.text FROM sys.dm_exec_requests requests CROSS APPLY sys.dm_exec_sql_text (requests.plan_handle) details WHERE requests.session_id > 50 ORDER BY total_elapsed_time DESC
This statement uses the plan handle from the requests table to call the table-valued function sys.dm_exec_sql_text to determine the text of the procedure that is being run. When I run the above query, I see this:
In case we weren’t sure what row was ours before we can tell now because the details.text column shows the text from our example stored procedure. Let’s talk about some other details in this output. The status column will tell you the current status of the request. Since we used the WAITFOR command to cause our program to freeze we see that the status is “suspended”. If this were an actual stored procedure you may see “running” here if a statement is currently executing or “suspended” if you are waiting on something (like a lock resource). For information on other values, check out this doc page.
Another useful piece of information is the command column. It will tell you what type of command is currently running. Again, in our case, the WAITFOR command pollutes this field but in a real world scenario this would tell you something such as “DELETE” or “INSERT” which can help you determine your problem area. At this point, if you still don’t know what statement the delay is caused by we can dig a little deeper with the information provided by sys.dm_exec_requests and sys.dm_exec_sql_text:
SELECT SUBSTRING(detail.text, requests.statement_start_offset / 2, (requests.statement_end_offset - requests.statement_start_offset) / 2) FROM sys.dm_exec_requests requests CROSS APPLY sys.dm_exec_sql_text (requests.plan_handle) detail WHERE requests.session_id = 67
Here, we do the same CROSS APPLY as before but we are more selective and only look at the row that interests us (it has session_id 67). Also, instead of looking at the entire sql text, we use the statement offsets provided by sys.dm_exec_requests to find the exact statement that is currently executing:
So, at this point, we know both the stored procedure and the statement that was executing when the delay was noticed. Now, as far as figuring out what the delay is caused by, that one is on you :).