Friday, March 23, 2012

External Activation and Receive Timeout

I have a set of service broker services setup that rely on external activation to process messages. I'm using the GotDotNet ExternalActivator, and it launches console applications that do the actual retrieval from the queues. The console applications are written to run continuously to avoid the cost of starting up .NET based console apps over and over again.

I am observing very odd timing behavior. With the receive queues empty and the external activator configured to run a minimum and maximum of 5 instances, I observe in SQL Profiler that most of the receive operations finish in about the same amount of time as my WAITFOR command in my receive stored procedure. However, there is usually one receive command that consistently takes upwards of 30 seconds and often causes sql timeout exceptions to be thrown. I know that I could code around this, but I wasn't really expecting this behavior.

Does anyone have any thoughts on why it might be occurring? I would have expected to routinely see my receive operations taking 15 seconds, give or take, especially when the queue is empty. Also, I have observed this behaviour on both SQL 2k5 Express and Dev Editions, so I don't think it's a version thing.

The stored procedure I am using to do the receive is:

Create PROCEDURE [dbo].[P_RTD_MessageBase_Receive]

@.receiving_queue_name varchar(255),

@.receiving_time_out int

AS

Declare @.receiveQuery nvarchar(300)

Set @.receiveQuery = 'WAITFOR(RECEIVE * FROM [dbo].['+ @.receiving_queue_name +']),

TIMEOUT ' + cast (@.receiving_time_out as varchar)

Execute sp_executeSql @.receiveQuery

Using SQL profiler can you find out if the actual command being executed has the correct timeout?

Some questions to help me understand why you made some design decisions:

1. Why do the apps run forever instead of shutting down after a long period of inactivity? Sure I understand you don't want yout .NET programs being launched and torn down over and over but you could use a longer timeout to avoid this. (Also, you should probably ngen your assemblies to improve startup time).

2. Why are you setting minimum instances to 5? Most people want minimum to be 0 so that there are no instances running when the queue is empty. Do all instances execute the same code path or are you doing something special here?

|||

I have confirmed that the actual command that seems to take much longer than the timeout has the correct timeout. IOW, I issue a receive with a 15000 ms timeout, and it takes about 28000 ms even though the queue is completely empty. The other four receives seems to finish and around 15000 ms consistently.

I don't have a great reason for the apps to run forever, except to avoid startup time. I could implement a longer timeout, but I am seeking to minimize the amount of time it takes to process a single message. The nature of the system is that messages drip in during some periods of the day, and I don't really want those messages to have to wait any longer than when messages are regularly coming in. nGen could help, but I still think my approach is the fastest.

I was setting the minimum instances to 5 in order to test the apps to make sure they weren't leaking any memory and that they did indeed run indefinitely.

How might these three issues affect the timeout?

|||

Is it possible for you to capture the trace using SQL Profiler with all Broker events as well as the following events enabled?

- RPC:Starting
- RPC:Completed
- SP:StmtStarting
- SP:StmtCompleted
- SP:Starting
- SP:Completed
- SQL:StmtStarting
- SQL:StmtCompleted
- SQL:BatchStarting
- SQL:BatchCompleted

You could e-mail that to rushi (dot) desai (at) microsoft (dot) com.

My questions were unrelated to the problem you are facing. I was intrigued by the atypical setup and so I was curious why you were using this setup.

Thanks,

Rushi

|||Hey Rushi - I just sent the trace file to you...|||

Rushi has come back to me and said that this is a bug. I have posted a bug report at:

https://connect.microsoft.com/SQLServer/feedback/ViewFeedback.aspx?FeedbackID=234866

No comments:

Post a Comment