How To Determine the Current Executing T-SQL Statement in a Long Running SQL Stored Procedure!!!

In this blog I just want to share the way by which you can Determine the Current Executing T-SQL Statement in a Long Running SQL Stored Procedure.

One day one of my team member was doing some update into a store procedure. Every time when he was executing the store procedure it was taking so much time. And he was not able to find the exact statement which was taking much time in execution. He called me and then using DMV's I have determined the exact statement which was the cause of this long running Store Procedure .The reason behind that was lock on table which was applied by some other transaction from different sessions which was having missing commit transaction statement :) :) Good Na :) And due to that the transaction from current procedure was not able to insert the data into that table, because it was in shared mode. 

In order to re-create the issue again, I'll create a Store procedure and then will put a wait for statement to create a manual long running store procedure. Then I'll show you the steps which we can follow.

I have the database TestDatabase. The name of the store procedure which I'm going to create is "TestSP".

USE TestDatabase

GO

CREATE PROCEDURE TestSP

AS

DECLARE @T1 TABLE (ID INT,Name char(20))

INSERT @T1 (id, Name) VALUES (1,'Vimal')

WAITFOR DELAY '02:00:00'

SELECT * FROM @T1

GO

Looking at store procedure you will notice that the procedure declares a temporary table, inserts ID and name,waits for 2 hours, and then I'm selecting the records from that table.

Now, to run the TestSP we have execute the below TSQL Statement. EXEC dbo.TestSP

Now it is in execution..So to dig down into the issue I'll use DMV's:

The dynamic management views (DMVs) in SQL Server 2005 are designed to give you a window

into what's going on inside SQL Server. They can provide information on what's currently happening inside the server as well as the objects it's storing. There are so many useful dynamic management views and functions which you can find at Microsoft online book.

Now I'm going to use the one of very frequently used DMV's i.e. sys.dm_exec_requests. It will return information about each request that is executing within SQL Server. There are so many useful columns which are the output of this DMV like session_id, request_id, start_time, status, command etc.

So I'm going to run below TSQL statement:

SELECT *

FROM sys.dm_exec_requests R

WHERE R.session_id > 50

ORDER BY total_elapsed_time DESC

I have taken session_id> 50 because the session_id which are less than 50 is used for system 

requests and the session_id which are greater than 50 are user request.

Running the above statement in a new query window in SSMS will give the following results. Please note that you can see more or less results with different ids when you run this on your server.

As we have few requests so you can identify which store procedure is running from a long time but in production databases, you may not be able to tell which stored procedure is running because high number of transactions. So in order to associate the currently running request with the stored procedure I will use the function sys.dm_exec_sql_text, which will take the plan_handle as parameter and will give the text of procedure which is running.

USE TestDatabase

Go

select R.session_id, R.status,R.command,R.statement_start_offset,R.statement_end_offset,

R.total_elapsed_time,S.text

from sys.dm_exec_requests R

cross apply sys.dm_exec_sql_text (R.plan_handle) S

where r.session_id > 50

order by total_elapsed_time desc

Now we have all text of procedure and the session_id for the same but still missing the statement in this procedure which is creating the problem...we can dig a little bit deeper with the information provided by sys.dm_exec_requests and sys.dm_exec_sql_text. Now I'll use statement_start_offset and statement_end_offset from sys.dm_exec_requests

USE TestDatabase

Go

SELECT SUBSTRING(S.text,

R.statement_start_offset / 2,

(R.statement_end_offset - R.statement_start_offset) / 2)

FROM sys.dm_exec_requests R

CROSS APPLY sys.dm_exec_sql_text (R.plan_handle) S

WHERE R.session_id = 67

Here, I have done the same CROSS APPLY as before but applied filters like session_id to get the records in which I'm interested i.e. session_id 67 . Also, instead of looking the entire store procedure text, I have used the statement_start_offset and statement_end_offset to find the exact statement that is currently executing.

So, Now at this point, we know stored procedure along with the statement that was executing when the delay was noticed.  This was just an example, in real world scenario you can get the wait types like INSERT, DELETE, CXPACKET etc..

Please correct me if I'm wrong at any place.....Comments and questions are welcome..... :)

Thank You!!!!