2012-06-26

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) = LEFT(CONVERT(nvarchar(128), @start, 127), 22) + N' : Start';
RAISERROR(@errmsg,0,0) WITH NOWAIT;

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

DECLARE @finish datetime2 = SYSDATETIME();
DECLARE @duration int = DATEDIFF(ms,@start,@finish);
SET @errmsg = LEFT(CONVERT(nvarchar(128), @finish, 127), 22) + N' : Finish after ' + CAST(@duration AS nvarchar(128)) + N' ms.';
RAISERROR(@errmsg,0,0) WITH NOWAIT;


I do the LEFT( ..., 22 ) on the timestamp in the message to increase readability of the output.
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.".

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.

No comments: