Best Practices - Stored Procedure Logging

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, bu开发者_如何学Ct 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

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.

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 ---

We generally use logging tables and take care around transactions. We pretty much avoid anything that involves going outside of SQL Server (e.g. writing to filesystem, calling external services, .NET assemblies, etc.)

We also try to avoid cursors -- is it possible your proc is long running because it's inefficient?

I use this procedure

CREATE PROCEDURE dbo.PrintLog (
    @Msg VARCHAR(2048)
    , @Option VARCHAR(100) = ''
    , @Separator VARCHAR(10) = '-'
    )
/*
@Option is a string containing possible values as B,A,D,T
if you want to print separator before message, include B
if you want to print separator after message, include A
if you want to print date, include D
if you want to print time, include T
Sample: 'BAD'

The order of characters does not matter. it is not case sensitive

Usage:
    exec dbo.PrintLog 'Timed Log', 'T'
    exec dbo.PrintLog 'Dated Log', 'D'
    exec dbo.PrintLog 'With Separator and Time', 'BT', '><'
    exec dbo.PrintLog 'With Separator and Date', 'BAD', '*'
    exec dbo.PrintLog 'With Separator and DateTime', 'BADT', 'x'
*/
AS
BEGIN
    declare @tempStr varchar(100)
    set @tempStr = replicate(@Separator, 50)
    IF charindex('B', upper(@Option)) > 0
        raiserror (@tempStr, 10, 1) with nowait

    DECLARE @prompt VARCHAR(max) = ''

    IF charindex('D', upper(@Option)) > 0
        SET @prompt = convert(VARCHAR, SysDatetime(), 101) + ' '

    IF charindex('T', upper(@Option)) > 0
        SET @prompt = @prompt + convert(VARCHAR, SysDatetime(), 108) + ' '
    SET @prompt = @prompt + @Msg

    raiserror (@prompt, 10, 1) with nowait

    set @tempStr = replicate(@Separator, 50)
    IF charindex('A', upper(@Option)) > 0
        raiserror (@tempStr, 10, 1) with nowait

    RETURN
END

GO

Usage

    exec dbo.PrintLog 'Date and Timed Log', 'DT'
    exec dbo.PrintLog 'Dated Log', 'D'
    exec dbo.PrintLog 'With Separator and Time', 'BT', '><'
    exec dbo.PrintLog 'With Separator and Date', 'BAD', '*'
    exec dbo.PrintLog 'With Separator and DateTime', 'BADT', 'x'

You also can change the parameter defaults to you desired values.