Estimate When Long Running SQL Processes Will Finish

I don’t know about you but I’m a fan of tips and tricks that make my life easier. Here is a quick tip that has saved me numerous times when it’s come to answering the question: “when will that <insert some specific process> be done?”

This tip is aimed at the Database Administrators out there because this question usually comes up in regards to backups, index maintenance, DBCC CHECKDB, restore, rollback, and even the occasional (gasp!) DBCC SHRINKFILE and usually involves someone standing over your shoulder in your office watching your screen and looking for answers which usually are not presented in a query window.

To make use of this tip you’ll need to have a working knowledge of the SQL Server Dynamic Management Objects. I’ll be focusing on those DMOs that involve active executions occurring on your SQL Server instance:

sys.dm_exec_requests
sys.dm_exec_sql_text

sys.dm_exec_requests exposes metadata for actively executing queries (aka requests) running on the local SQL Server instance while sys.dm_exec_sql_text is a function that, when passing in a sql_handle (a unique identifier for a batch of t-sql text running on your server) will return the t-sql text.

The end results of this query will be any actively-executing request where the percent_complete column in sys.dm_exec_requests is populated.

This is a key point to understand since not all types of operations provide a percent_complete value. According to the official documentation for this Dynamic Management Object those operations that do provide this metric are:

ALTER INDEX REORGANIZE
AUTO_SHRINK option with ALTER DATABASE
BACKUP DATABASE
DBCC CHECKDB
DBCC CHECKFILEGROUP
DBCC CHECKTABLE
DBCC INDEXDEFRAG
DBCC SHRINKDATABASE
DBCC SHRINKFILE
RECOVERY
RESTORE DATABASE
ROLLBACK
TDE ENCRYPTION

sys.dm_exec_requests provides the sql_handle that sys.dm_exec_sql_text needs to return the actual batch command for the request. sys.dm_exec_requests also provides information via two columns: statement_start_offset and statement_end_offset that will identify the current statement in the batch that is executing at the time. The current session is eliminated from the results by use of the @@spid predicate.

The query that I’m providing in this article is shown below. When run it will return the following KPIs when there is activity of one of the types mentioned above actively executing:

session_id – the unique identifier for a session on the local SQL Server instance
percent_complete – current percent complete for the request being executed
elapsed_seconds – how long has this process been running in seconds
wait_type – if this process is waiting for resources then what is the wait type?
wait_time – accumulated wait time in milliseconds
last_wait_type – the previous wait time if there was a period of waiting prior to the current wait situation
est_completion_time – based upon the rate of execution to-date this is a computed column that provides a fairly accurate estimate of when the process will complete.
batch_text – the full statement being executed as part of the request
statement_executing – the active statement in the batch being run now

SET NOCOUNT ON;

SELECT R.session_id
	, R.percent_complete
	, R.total_elapsed_time/1000 AS elapsed_seconds
	, R.wait_type
	, R.wait_time
	, R.last_wait_type
	, DATEADD(s,100/((R.percent_complete)/ (R.total_elapsed_time/1000)), R.start_time) AS est_complete_time
	, ST.text AS batch_text

	, CAST(SUBSTRING(ST.text, R.statement_start_offset / 2, 
		(
			CASE WHEN R.statement_end_offset = -1 THEN DATALENGTH(ST.text)
			ELSE R.statement_end_offset
			END - R.statement_start_offset 
		) / 2 
	) AS varchar(1024)) AS statement_executing
FROM sys.dm_exec_requests AS R
	CROSS APPLY sys.dm_exec_sql_text(R.sql_handle) AS ST
WHERE R.percent_complete > 0
	AND R.session_id <> @@spid;

In order to see this in action I’ll use the following batch of t-sql text:

--First DBCC
DBCC CHECKDB (FOO);

--Then Backup
BACKUP DATABASE [FOO] TO  DISK = N'C:\SQL\Backup\FOO.bak' 
WITH NOFORMAT, 
	NOINIT,  
	NAME = N'FOO-Full Database Backup', 
	SKIP, NOREWIND, NOUNLOAD, COMPRESSION,  
	STATS = 10
GO

If I highlight and run just the first command (the DBCC CHECKDB command) then kick off the query that gives us completion data immediately after the doing so the results will look like this:

session_id – 61
percent_complete – 19.61156
elapsed_seconds – 2
wait_type – CXPACKET
wait_time – 2186
last_wait_type - CXPACKET
est_completion_time – 2017-04-30 20:13:21.590
batch_text – --First DBCC DBCC CHECKDB (FOO); --Then Backup BACKUP DATABASE [FOO] TO DISK = N'C:\SQL\Backup\FOO.bak' WITH NOFORMAT, NOINIT, NAME = N'FOO-Full Database Backup', SKIP, NOREWIND, NOUNLOAD, COMPRESSION, STATS = 10
statement_executing – BACKUP DATABASE [FOO] TO DISK = N'C:\SQL\Backup\FOO.bak' WITH NOFORMAT, NOINIT, NAME = N'FOO-Full Database Backup', SKIP, NOREWIND, NOUNLOAD, COMPRESSION, STATS = 10

If I execute the full batch consisting of the DBCC CHECKDB command and the BACKUP command and wait for the backup to start before I query for completion information this is what the results look like:

session_id – 61
percent_complete – 6.930882
elapsed_seconds – 13
wait_type – ASYNC_IO_COMPLETION
wait_time – 1007
last_wait_type - ASYNC_IO_COMPLETION
est_completion_time – 2017-04-30 20:17:59.613
batch_text – --First DBCC DBCC CHECKDB (FOO); --Then Backup BACKUP DATABASE [FOO] TO DISK = N'C:\SQL\Backup\FOO.bak' WITH NOFORMAT, NOINIT, NAME = N'FOO-Full Database Backup', SKIP, NOREWIND, NOUNLOAD, COMPRESSION, STATS = 10
statement_executing – BACKUP DATABASE [FOO] TO DISK = N'C:\SQL\Backup\FOO.bak' WITH NOFORMAT, NOINIT, NAME = N'FOO-Full Database Backup', SKIP, NOREWIND, NOUNLOAD, COMPRESSION, STATS = 10

Of course, in this example I’m using a local database on my laptop to provide these results so the completion time isn’t that far in the future. Imagine the insights you can gain should we be dealing with a 20TB database as I often do. I created this script almost 10 years ago and still regularly use it. The last time was less than a week ago after getting paged at 2am because of a failed ETL process that was dependent on a backup process that was running long. It took me longer to log in than it did to identify when the backup would complete and then change the SQL Agent Job that failed to execute after that estimated execution time. Instead of staying up for another 30 minutes I returned to bed before my pillow even cooled.

Comments

Plain text