Best Practices - Stored Procedure Logging

Question

If you have a long running SP, do you log somehow its actions or just wait for this message?

"Command(s) completed successfully."

I assume, that there can be plenty solutions on this subject, but is there any best practice - a simple solution that is frequently used?

EDIT

I've found an interesting link on this subject

http://weblogs.sqlteam.com/brettk/archive/2006/09/21/12391.aspx

Article describes using a log table, but there's an issue

The logging procedure must be executed outside of any transaction

I can't call that insert outside, because of cursor that I use and insert a line to that table on every row.

Any ideas?

EDIT 2

Digging..

there's a xp_logevent in SQL Server. Did you try it?

What about SQL Server Profiler?

There's also Creating Log file for Stored Procedure

Answer 1

How are you invoking the stored procedure? If it is through Management Studio then you can easily print out the message as follows

RAISERROR ('Some debugging info', 0, 1) WITH NOWAIT 

This is preferable to using PRINT as the message will appear immediately. These messages can also be caught in ADO.NET by wiring up a handler for the Connection.InfoMessage event.

I see that you have already listed SQL Profiler as a possibility. You might be interested to know that you can log your own user configurable events that can be seen in SQL Profiler.

Answer 2

In order to see how long things are taking, and how many rows the previous action modified, I add the current date + time and the last row count to every entry. I use this procedure:

CREATE PROCEDURE dbo.[Log]     @Message NVARCHAR(512),     @RowCount INT = null OUTPUT,     @Delimiter NCHAR(1) = N' ',     @PadChar NCHAR(1) = N'-' AS     BEGIN         SET @RowCount = @@ROWCOUNT;          DECLARE @LogDate AS NVARCHAR(50);         DECLARE @RowCountPadded AS NCHAR(8);          SET @LogDate = CONVERT(NVARCHAR(50),GETDATE(),121);         SELECT @RowCountPadded = CASE @RowCount WHEN 0 THEN REPLICATE(@PadChar,8) ELSE REPLACE(STR(@RowCount, 8), SPACE(1), @PadChar) END;           SET @Message = @LogDate + @Delimiter + @RowCountPadded + @Delimiter + @Message;         RAISERROR (@Message, 0, 1) WITH NOWAIT;     END 

So, in your procedures, add log output like this:

EXEC dbo.[Log] 'the message'; 

It produces this:

2012-12-28 11:28:25.197 -------- the message 

Had you performed some action previously, you'd see the row count where the dashes are. If you needed the row count for something else (e.g. to log to a table), you can get it back from the procedure as an OUTPUT parameter.

UPDATE: Use this gist if you want to create this procedure once and use it everywhere.

-- removed lines ---