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

Any sp, that is more than a couple of selects and updates. For example, if you use cursor and you need to watch progress. Is anything wrong with my question? — hgulyan, May 30 '10 at 09:55

score 25 · Accepted Answer · answered May 30 '10 at 14:48

25

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.

answered May 30 '10 at 14:48

Martin Smith

438,706
87
741
845

1

I'm invoking sp in management studio, but the question is general, so if there's a nice way of logging, it can be used in application also. I don't need RAISERROR, because I need to log process, not errors. PRINT can be an option, but what if sp prints like 1000 rows per second? I've already tried SQL Profiler. It's a nice option, but it's not really a logging. It's more monitoring, I suppose and profiler isn't a general solution. Maybe solution is combining all that was told here. – hgulyan May 30 '10 at 14:56
1

Don't be confused by the name RAISERROR is not just for errors. Anything with severity of less than 10 is just for info messages. Clearly whatever logging framework you use you need to design it such that an appropriate amount of information is being logged. – Martin Smith May 30 '10 at 15:03
Won't Raiserror stop the sp? p.s. and thank you for custom user configuration in profiler. thanks most interesting link on this topic. – hgulyan May 30 '10 at 15:05
2

No. It won't stop the SP because the severity level is low. For details see http://msdn.microsoft.com/en-us/library/ms178592.aspx – Martin Smith May 30 '10 at 15:10
Ok, I got it, but what's the difference between raiserror and a simple print if it's only for info messages? – hgulyan May 30 '10 at 15:15
1

With `Print` you won't get the message back till the stored procedure ends (I think - Or at the very least you'll have to wait for it) `RAISERROR ... WITH NOWAIT` avoids that issue. Infact according to this link. A print statement *is* just "a message on severity level 0." http://www.sommarskog.se/error-handling-I.html – Martin Smith May 30 '10 at 15:27
4

The print output is buffered, and so you won't see the results right away and they can come out of order with the error stream, which is buffered separately. Since raiserror uses the separate buffer which can force to flush on each statement (the `WITH NOWAIT` directive), it's better for most logging purposes. – Joel Coehoorn May 30 '10 at 17:22
@Martin Smith, After our conversation, I read your answer for the second time, and it's absolutely right and simple answer. – hgulyan May 31 '10 at 04:44

score 16 · Answer 2 · edited Jan 05 '19 at 04:15

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

score 3 · Answer 3 · answered May 30 '10 at 14:47

3

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?

answered May 30 '10 at 14:47

Joe

41,484
20
104
125

Can you be more specific? What if you can't insert to your log table outside a transaction? I know, that cursors are not recommended, but it's one time used script and there's no other way, so this is a case when cursors are necessary. – hgulyan May 30 '10 at 14:51

score 2 · Answer 4 · answered Feb 16 '16 at 23:54

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.

Best Practices - Stored Procedure Logging

4 Answers4

Linked