Queueing with cflock on Coldfusion 9

Report · Jun 23, 2010

We've been dealing with a problem with our event gateways since we upgraded from ColdFusion 8 Enterprise to ColdFusion 9 Enterprise.

We have an event gateway setup to establish a connection to a third party. They went us updates at least every 10 seconds and sometimes many times a second.

We have a Java class configured as the Event Gateway listener, and it pushes events and data to a CFC function. In that function we actually use a *named* <cflock> to ensure that requests are dealt with in order, and requests will be queued at this point to have exclusive access to the named lock. This lock has a *30 second* timeout.

I've also got lots of debugging in this function, and I've noticed a few things:

Requests will queue up before the <cflock> tag, waiting for the lock, and this queue can be over 40 events long
All requests are processed when they get the lock within 6 seconds. The average is actually 1.5 to 2 sec from when they get the lock to when they complete processing

So the problem is that, now and again, I will have a lock timeout occur, and it's after 30 seconds. First I log if the request is waiting for the lock. It looks like this:

"Information","Thread-23","06/23/10","15:45:18","APP1","F4B42A5A-F34D-C614-DE01B150E6906F78 (1277304318606) : PRE LOCK"

And then further down the logs, I see this for the same request:

"Error","Thread-23","06/23/10","15:45:48","APP1","F4B42A5A-F34D-C614-DE01B150E6906F78 (1277304348607) : LOCK ERROR: A timeout occurred while attempting to lock lock_ResponseDispatcher."

There's 30 seconds between them. The requests and any event data associated with it is lost at this point. Not good for me.

So I thought I'd see if the queue was being processed fast enough. I'm unsure how events are queued by <cflock>. Is there a hard limit?

Anyway, on this particular run, I saw that:

The request went onto the queue when there was 6 requests there already, so it's number 7 in the queuea

Over the next 30 seconds about 17 requests are removed from the queue

About the same number of requests are added to the queue

In this period, the request in question is not processed and after 30 seconds times out

I can't believe my eyes! It's as if the <cflock> queue is not processed as first in first out (FIFO), but first in last out (FILO)!

Is such a thing possible? Has anyone else every seen this kind of behaviour?

Many thanks in advance to anyone with any thoughts.

Ciaran

Report · Jun 25, 2010

If anyone is interested, I've updated this topic having figured out the issue over on Stackoverflow.com:

http://stackoverflow.com/questions/3103572/queueing-with-cflock-on-coldfusion-9