Often, you have some code that is taking a long time, and you want to know how much time sections of the code is taking, and you likely want to know immediately as your code executes. In this blog I will talk about a couple of the techniques you can use to make this happen, either in a permanent manner, as well so in a message.

The first method I will discuss is to create a log table, and insert rows along the way as you work through the code. For example, say we have 10 steps in a process, which I will simulate with a WHILE loop, after creating a simple log table.

USE tempdb;
GO

--simple version of the table, probably enhance with things like what module is running, --name of step running, etc.
CREATE TABLE dbo.logCodeStep (msg nvarchar(100), logTime datetime2(2) DEFAULT (SYSDATETIME()))
GO

DECLARE @i INT = 1, @msg NVARCHAR(100)
WHILE @i <= 10
  BEGIN
     INSERT INTO dbo.logCodeStep(msg)
     VALUES(CONCAT('Iteration:', @i));

     WAITFOR DELAY '00:00:01'; --wait one second
     SET @i = @i + 1;
  END;
GO

Now while the code is running, you can query dbo.logCodeStep to see what has been output so far, and you can see it later if desired, perhaps to compare runtimes. I have a table in many of my databases (along with a stored procedure to encapsulate the call) to capture runtimes of various processes that I want to watch the run times of.

SELECT *
FROM   dbo.logCodeStep

msg              logTime
---------------- ---------------------------
Iteration:1      2018-02-07 20:37:41.38
Iteration:2      2018-02-07 20:37:42.39
…
Iteration:9      2018-02-07 20:37:49.42
Iteration:10     2018-02-07 20:37:50.42

Sometimes, though, you simply want to print out a message for each iteration, so you try something like:

DECLARE @i INT = 1, @msg NVARCHAR(100), @startTime datetime2(4) = SYSDATETIME()
WHILE @i <= 10
  BEGIN
     SET @msg = CONCAT('Iteration:', @i, ' ', DATEDIFF(MILLISECOND,@startTime,SYSDATETIME())/1000.0 , 'sec elapsed.')
     PRINT @msg

     WAITFOR DELAY '00:00:01'; --wait one second
     SET @i = @i + 1;
  END;

I know, I did this just today (which inspired me to write this blog, naturally). Run it and what you will notice is that for 10 seconds, it looks like nothing has happened. Then you get all 10 messages printed out immediately:

Iteration:1 0.000000sec elapsed.
Iteration:2 1.007000sec elapsed.
…
Iteration:9 8.023000sec elapsed.
Iteration:10 9.025000sec elapsed.

For a process that runs for 10 seconds, this is no problem at all. But when you are doing 100s of loops, and they take time, you don’t want to wait. Eventually, data will start spurting out, but not immediately. We want immediately, even if it isn’t the optimum way.

The PRINT statement won’t output immediately, but its cousin, good old RAISERROR, does. Using a severity of 10 for the message, the message will be output just like a PRINT message. Then, adding WITH NOWAIT to the RAISERROR, the messages will no longer be queued for output, and will be returned immediately. Run the following batch:

DECLARE @i INT = 1, @msg NVARCHAR(100), @startTime datetime2(4) = SYSDATETIME()
WHILE @i <= 10
  BEGIN
    SET @msg = CONCAT('Iteration:', @i, ' ', DATEDIFF(MILLISECOND,@startTime,SYSDATETIME())/1000.0 , 'sec elapsed.')
    RAISERROR (@msg, 10,1) WITH NOWAIT; --use 10 or 0 and it behaves like PRINT. Other severities will have more message information

    WAITFOR DELAY '00:00:01'; --wait one second
    SET @i = @i + 1;
END;

And you will see 10 messages returned independently, one after the other. This is really cool. It has one kind of interesting side effect as well. The result sets that are output will also no longer be cached. To see this phenomena, check out the following batch.

I have added a variable named @includeStatusFlag. If this value is 1, it will output the RAISERROR value, and if 0, then it will not. I also included a query of the sys.objects table to show how it will affect those results.

DECLARE @i INT = 1, @msg NVARCHAR(100), @startTime datetime2(4) = SYSDATETIME(), @includeStatusFlag bit = 1 --control if the RAISERROR is fired
WHILE @i <= 10
  BEGIN
    SET @msg = CONCAT('Iteration:', @i, ' ', DATEDIFF(MILLISECOND,@startTime,SYSDATETIME())/1000.0 , 'sec elapsed.')
    IF @includeStatusFlag = 1
       RAISERROR (@msg, 10,1) WITH NOWAIT;
    SELECT TOP 1 @i, name FROM sys.objects --so it is definitely a "real" query, and not just a value

    WAITFOR DELAY '00:00:01'; --wait one second
    SET @i = @i + 1;
END;

When the status messages are not returned, 10 seconds pass, then the 10 result sets simultaneously are output. When they are returned, the buffered results are output, then the message. So it doesn’t send the messages out of order, which might seem the intuitive thing if you are a procedural programmer, but it preserves the order of the output.

Note: I am not the only person to have written on this subject, and probably will not be the last. For example I found this one from 2012 when I was researching http://sqlity.net/en/984/print-vs-raiserror/ that covers more of the details than I covered in terms of the statements. There was no author listed there, but here https://www.mssqltips.com/sqlservertip/1660/using-the-nowait-option-with-the-sql-server-raiserror-statement/ Andy Novick covers some of the same details as well. Post in the comments if you know of other articles I should link to.