Logging in T-SQL scripts

I am working on a major version upgrade of a system that is using SharePoint and private databases. In both cases with 100+ GB data. Most database parts are scripted, and some tasks are running for hours.
Still it is important to the planning to know the execution time of the tasks and their steps.

This logging and timing I have done by wrapping the steps in some messages:
DECLARE @start datetime2 = SYSDATETIME();
DECLARE @errmsg nvarchar(2047) = CONVERT(nchar(23), @start, 126) + N'Z : Start';
RAISERROR(@errmsg,0,0) WITH NOWAIT;

-- Do something
WAITFOR DELAY '00:00:04';  -- HH:mm:ss

DECLARE @finish datetime2 = SYSDATETIME();
DECLARE @duration int = DATEDIFF(ms, @start, @finish);
SET @errmsg = CONVERT(nchar(23), @finish, 126) + N'Z : Finish after %i ms.';
RAISERROR(@errmsg, 0,0, @duration) WITH NOWAIT;

The duration of the step is in this case measured in milliseconds (ms), but could be measured in another unit. Unfortunately this unit can not be in a parameter, or as they say in the documentation on DATEDIFF() „User-defined variable equivalents are not valid.“.

I do prefer RAISERROR to PRINT to log in T-SQL. There are many discussions about this, but my take is that with RAISERROR ... WITH NOWAIT I will get the message immidiately and not when the batch block is finished and the PRINT–queue is processed.

PowerShell thoughts

To get a readable duration instead of a lot of ms like 56135000 you can create a TimeSpan object in PowerShell.
PS> \([System.TimeSpan]::FromMilliseconds(56135000)).ToString()
This will give a formatted timespan
15:35:35
Which is 15 hours, 35 minutes and 35 seconds.

If I have a larger script file with several steps, I would go for a PowerShell solution as I then would have better possibilities to log and use general parameters.

History

2012-06-26 Entry created.
2015-02-05 Section about TimeSpan object added.
2023-02-23 Formatting on @duration changed to conversion specification. And timestamp simplyfied.