Queueing with cflock on Coldfusion 9

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-DE01B150E6906F 78 (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