So you have a SQL server stored procedure for logging, and its running a little slower than you like. There is no output, you just need to make sure the log message is put into the system. It would be really nice if there were a way to say "run this, and the client doesn't need to wait for a response", but unfortunately that's not a simple built-in feature. So how do you do it, with a minimum of headache?
Much of the credit for this goes to
http://rusanu.com/2009/08/05/asynchronous-procedure-execution/. That post solves a slightly different problem - you want to execute a slow stored procedure that has no inputs, and check back later for the output -- without leaving a SQL connection open. But it was the basis of my solution here.
First, we setup a trivial example -- the destination table for the log message, and the stored procedure, which is slow but eventually does the insert. We will want to see what happens if the stored procedure fails, so we'll have a simple check to force an error.
CREATE TABLE
[LogDestination]([LogValue] [varchar](max));
GO
CREATE PROCEDURE
[usp_SlowProcedure]
@message VARCHAR(MAX) AS
BEGIN
WAITFOR DELAY
'0:00:00.5' -- wait
1/2 second
IF @message LIKE
'%ERROR%'
raiserror(@message, 16, 10);
ELSE
INSERT INTO
[LogDestination]([LogValue]) VALUES(@message);
END
GO
The solution will involve creating a QUEUE and a SERVICE, so you need to make sure your database has the Service Broker turned on. You can do that with this command:
ALTER DATABASE [MyDatabase] SET ENABLE_BROKER;
It sometimes seems to run forever -- it won't want to finish if there are any connections open on the database. You can force those to be closed with this option:
ALTER DATABASE [MyDatabase] SET ENABLE_BROKER WITH ROLLBACK IMMEDIATE;
Now to start creating the new objects. For reasons of circular dependencies, you have to CREATE one of these first, and then ALTER it later. That's just the breaks. Let's put down the fundamental parts:
CREATE PROCEDURE
[usp_AsyncExecActivated] AS
PRINT 'placeholder'
GO
CREATE QUEUE
[AsyncExecQueue]
WITH ACTIVATION(STATUS = ON
,PROCEDURE_NAME =
[usp_AsyncExecActivated]
,MAX_QUEUE_READERS = 1
,EXECUTE AS OWNER)
GO
CREATE SERVICE
[AsyncExecService] ON QUEUE
[AsyncExecQueue] ([DEFAULT]);
GO
CREATE PROCEDURE
[usp_SlowProcedureAsync]
@message VARCHAR(MAX)
AS
BEGIN
SET NOCOUNT
ON;
DECLARE @h UNIQUEIDENTIFIER;
BEGIN DIALOG CONVERSATION
@h
FROM SERVICE [AsyncExecService]
TO SERVICE 'AsyncExecService'
WITH ENCRYPTION = OFF;
SEND ON
CONVERSATION @h (@message);
END CONVERSATION
@h;
END
GO
Now we have:
- [AsyncExecQueue] - the queue to hold the messages on
- [AsyncExecService] - because only a service can write to a queue
- [usp_AsyncExecActivated] - stored procedure that will run in the background whenever the queue is written to
- [usp_SlowProcedureAsync] - to wrap all this up with, hiding the mess from the users. It has the same signature as [usp_SlowProcedure], but will return immediately.
One more consideration -- since this is completely asynchronous, the only errors the client can get are if the database is offline, out of space, etc. But if [usp_SlowProcedure] has an error, we want a table to just shove that input into, without leaving it on the queue. Or I guess you could omit this part, and the code that writes to it.
CREATE TABLE
[AsyncErrored]([LogValue] [varbinary](max), [ErrorTime] DATETIME2
DEFAULT SYSDATETIME());
GO
Now we ALTER the background stored procedure, which is still just a placeholder, to actually do the processing.
ALTER PROCEDURE
usp_AsyncExecActivated
AS
BEGIN
SET NOCOUNT
ON;
DECLARE @h UNIQUEIDENTIFIER
= NULL
,
@messageTypeName SYSNAME = NULL
,
@messageBody VARBINARY(MAX) = NULL;
RECEIVE TOP(1)
@h =
[conversation_handle]
, @messageTypeName = [message_type_name]
, @messageBody =
[message_body]
FROM [AsyncExecQueue];
WHILE (@h IS
NOT NULL)
BEGIN
BEGIN TRY
DECLARE
@message VARCHAR(MAX) = CAST(@messageBody AS VARCHAR(MAX));
EXECUTE
[usp_SlowProcedure] @MESSAGE
END TRY
BEGIN CATCH
INSERT INTO [AsyncErrored]([LogValue]) VALUES(@messageBody);
END CATCH
END CONVERSATION
@h WITH CLEANUP;
SET @h =
NULL;
RECEIVE TOP(1)
@h =
[conversation_handle]
,
@messageTypeName = [message_type_name]
,
@messageBody = [message_body]
FROM [AsyncExecQueue];
END -- WHILE
END --
PROCEDURE usp_AsyncExecActivated
GO
That's all there is to it. But what good is a bunch of tables without running some tests to see it in action?
DECLARE @countQueue VARCHAR(10), @countDestination VARCHAR(10), @countErrored VARCHAR(10)
PRINT CAST(CAST(SYSDATETIME() AS TIME) AS VARCHAR(11)) + ' Test 1: invoke
[usp_SlowProcedureAsync] one time with simple input.'
EXECUTE [usp_SlowProcedureAsync] 'Test input message';
SET @countQueue = (SELECT COUNT(1) FROM
[AsyncExecQueue])
SET @countDestination = (SELECT COUNT(1) FROM
[LogDestination])
SET @countErrored = (SELECT COUNT(1) FROM [AsyncErrored])
PRINT CAST(CAST(SYSDATETIME() AS TIME) AS VARCHAR(11)) + ' Queue=' + @countQueue + ' Destination=' +
@countDestination + '
Errored=' + @countErrored
WHILE (@countQueue <> '0')
BEGIN
WAITFOR DELAY
'0:00:00.2'
SET @countQueue = (SELECT COUNT(1) FROM [AsyncExecQueue])
SET @countDestination = (SELECT COUNT(1) FROM
[LogDestination])
SET @countErrored = (SELECT COUNT(1) FROM [AsyncErrored])
PRINT CAST(CAST(SYSDATETIME() AS TIME) AS VARCHAR(11)) + ' Queue=' + @countQueue + ' Destination=' +
@countDestination + '
Errored=' + @countErrored
END
DELETE FROM
[LogDestination];
DELETE FROM
[AsyncErrored];
PRINT CAST(CAST(SYSDATETIME() AS TIME) AS VARCHAR(11)) + ' Test 2: invoke
[usp_SlowProcedureAsync] five times, with fourth causing an error in
[usp_SlowProcedure].'
EXECUTE [usp_SlowProcedureAsync] 'Test message 1';
EXECUTE [usp_SlowProcedureAsync] 'Test message 2';
EXECUTE [usp_SlowProcedureAsync] 'Test message 3';
EXECUTE [usp_SlowProcedureAsync] 'Test ERROR 4';
EXECUTE [usp_SlowProcedureAsync] 'Test message 5';
SET @countQueue = (SELECT COUNT(1) FROM
[AsyncExecQueue])
SET @countDestination = (SELECT COUNT(1) FROM
[LogDestination])
SET @countErrored = (SELECT COUNT(1) FROM [AsyncErrored])
PRINT CAST(CAST(SYSDATETIME() AS TIME) AS VARCHAR(11)) + ' Queue=' + @countQueue + ' Destination=' +
@countDestination + '
Errored=' + @countErrored
WHILE (@countQueue <> '0')
BEGIN
WAITFOR DELAY
'0:00:00.2'
SET @countQueue = (SELECT COUNT(1) FROM [AsyncExecQueue])
SET @countDestination = (SELECT COUNT(1) FROM
[LogDestination])
SET @countErrored = (SELECT COUNT(1) FROM [AsyncErrored])
PRINT CAST(CAST(SYSDATETIME() AS TIME) AS VARCHAR(11)) + ' Queue=' + @countQueue + ' Destination=' +
@countDestination + '
Errored=' + @countErrored
END
Here's some output I got from the above test run. You can see the 1/2 second pauses between each insert being processed.
15:59:16.62 Test 1: invoke
[usp_SlowProcedureAsync] one time with simple input.
15:59:16.85 Queue=2 Destination=0
Errored=0
15:59:17.07 Queue=1 Destination=0
Errored=0
15:59:17.28 Queue=1 Destination=0
Errored=0
15:59:17.48 Queue=0 Destination=1
Errored=0
(1 row(s) affected)
(0 row(s) affected)
15:59:17.48 Test 2: invoke
[usp_SlowProcedureAsync] five times, with fourth causing an error in
[usp_SlowProcedure].
15:59:17.48 Queue=9 Destination=0
Errored=0
15:59:17.70 Queue=9 Destination=0
Errored=0
15:59:17.90 Queue=9 Destination=0
Errored=0
15:59:18.10 Queue=7 Destination=1
Errored=0
15:59:18.30 Queue=7 Destination=1
Errored=0
15:59:18.51 Queue=7 Destination=2
Errored=0
15:59:18.71 Queue=5 Destination=2
Errored=0
15:59:18.91 Queue=5 Destination=2
Errored=0
15:59:19.12 Queue=3 Destination=3
Errored=0
15:59:19.32 Queue=3 Destination=3
Errored=0
15:59:19.52 Queue=3 Destination=3
Errored=0
15:59:19.72 Queue=1 Destination=3
Errored=1
15:59:19.93 Queue=1 Destination=3
Errored=1
15:59:20.13 Queue=0 Destination=4
Errored=1
And if you run all of that SQL, and are done playing with it, here's the easy clean-up:
DROP TABLE
[LogDestination]
DROP PROCEDURE
[usp_SlowProcedure]
DROP TABLE
[AsyncErrored]
DROP PROCEDURE
[usp_AsyncExecActivated]
DROP SERVICE
[AsyncExecService]
DROP PROCEDURE
[usp_SlowProcedureAsync]
DROP QUEUE
[AsyncExecQueue]
I hope someone eventually finds this useful; but if not, I will hopefully remember that I put this out here =-]
