5

We have a group of fairly complex stored procedures that process a transaction queue on a round the clock schedule. These scripts use a number of print statements to document what is being done to aid in debugging.

I want to keep this information while it is running in production (as an SQL Server Agent job) to help with troubleshooting when something goes wrong. I have looked at this site which has a fairly good method of saving the print output but it also has some downsides (output is not available until the script completes, etc). It also requires SSIS or DTS which I have no experience with.

I have thought of changing all of the print statements to insert statements to a log table. The problem is that much of the work we need debug info for is under transaction control and if there is an error, all of the log information would be rolled back with the actual transaction.

Does anyone have a better solution or an idea of how to work either of the solutions I have looked at above?

Improve this question
1

2 Answers 2

Reset to default
4

One solution to the rollback problem is to log information to a table variable (which isn't affected by the transaction), then roll back, then insert into the real logging table. Quick example:

DECLARE @LogRow TABLE
(
  dt DATETIME, objectid INT, 
  errornumber INT /* other columns */
);

BEGIN TRANSACTION;

BEGIN TRY

  SELECT 1/0;

  COMMIT TRANSACTION;

END TRY
BEGIN CATCH

  INSERT @LogRow(dt, objectid, errornumber /* , ... */)
    SELECT SYSDATETIME(), @@PROCID, ERROR_NUMBER() /* , ... */;

  ROLLBACK TRANSACTION;

  INSERT dbo.RealLogTable(/*...columns...*/) 
    SELECT /*...columns...*/ FROM @LogRow;

END CATCH
Improve this answer
6
  • Can the log table be created in the root SP and shared among all called sub-SPs?
    – Caynadian
    Commented Mar 27, 2014 at 16:24
  • 2
    @Caynadian Well you could use a Table-Valued Parameter (TVP) for that, but perhaps you should step back and not have procedures calling procedures calling procedures...
    – Aaron Bertrand
    Commented Mar 27, 2014 at 16:38
  • Well, we have one root SP that then calls 3 primary processing sub-SPs. The 3 sub-SPs all do similar things so those similar functions are broken out in to sub-sub-SPs. Combining everything back in to 1 SP would result in a nightmarishly huge SP that would be impossible to work with. I will try out what you've suggested, thanks!
    – Caynadian
    Commented Mar 27, 2014 at 17:03
  • 1
    Yikes, I'll take one procedure over a dozen in terms of "impossible to work with"... YMMV.
    – Aaron Bertrand
    Commented Mar 27, 2014 at 17:15
  • Well, unfortunately, TVPs won't work as they are readonly when passed to the sub-SPs.
    – Caynadian
    Commented Mar 27, 2014 at 19:25
1

In the end, we used the SSIS package with a script that captured the print statements as illustrated in the link in my original question. The captured print output is put in to the SSIS log which can then be directed to a CSV file, XML file, database, etc. (we used a database table). We then run the SSIS package using an SQL Server Agent job (just make sure the SQL Agent user has access to the table you are outputting the logs to).

Although this was simpler due to the complexity of the SPs we are using, it was not ideal. I did try the suggestion from @AaronBertrand above and it does work to enable logging despite using transactions.

Improve this answer
6
  • I'm confused, you were using transactions already, no? Hence: The problem with this is that much of the work we need debug info for is under transaction control and if there is an error, all of the log information would be rolled back with the actual transaction. I wasn't suggesting adding additional transaction code on top of that, just using the transactions you already had in the way I described. shrug I guess if you find it easier to capture print output...
    – Aaron Bertrand
    Commented Apr 1, 2014 at 16:19
  • The problem is that transactions are started in one SP and then not committed until after one or more sub-SPs are executed. So unless there was a way to pass around the table variable from one SP to another, it wouldn't work for us.
    – Caynadian
    Commented Apr 1, 2014 at 20:22
  • Your example was great, it just wouldn't work for us unfortunately. The way we went is far from perfect because the print output is not captured in real time but in batches. If the SP hangs in the middle, there is no way to find out what happened without killing it first.
    – Caynadian
    Commented Apr 1, 2014 at 20:23
  • I still don't understand why each stored procedure can't log its own errors or why you have to pass all of the errors around from procedure to procedure to procedure. shrug Anyway, you can try using RAISERROR('foo',0,1) WITH NOWAIT; instead of PRINT - the NOWAIT forces it to flush regardless of the current output buffer - should be much more real time (though there may be an upper bound on buffer size still).
    – Aaron Bertrand
    Commented Apr 1, 2014 at 20:40
  • 1
    no, did you try it? The parameters 0,1 are there for a reason...
    – Aaron Bertrand
    Commented Apr 1, 2014 at 20:52

Your Answer

By clicking “Post Your Answer”, you agree to our terms of service and acknowledge you have read our privacy policy.

Not the answer you're looking for? Browse other questions tagged or ask your own question.