Очередь с cflock на Coldfusion 9 - PullRequest
Новая
       18

Очередь с cflock на Coldfusion 9

3 голосов
/ 23 июня 2010

Мы столкнулись с проблемой наших шлюзов событий с момента перехода с ColdFusion 8 Enterprise на ColdFusion 9 Enterprise.

У нас есть настройка шлюза событий для установления соединения с третьей стороной. Они отправляли нам обновления как минимум каждые 10 секунд, а иногда и много раз в секунду.

У нас есть класс Java, настроенный в качестве прослушивателя шлюза событий, и он передает события и данные в функцию CFC. В этой функции мы фактически используем с именем <cflock>, чтобы гарантировать, что запросы обрабатываются по порядку, и на этом этапе запросы будут поставлены в очередь, чтобы иметь эксклюзивный доступ к именованной блокировке. Эта блокировка имеет время ожидания 30 секунд .

У меня также есть много отладок в этой функции, и я заметил несколько вещей:

  • Requetst будет стоять в очереди до тега <cflock>, ожидая блокировки, и эта очередь может иметь длину более 40 событий
  • Все запросы обрабатываются, когда они получают блокировку в течение 6 секунд. Среднее значение составляет от 1,5 до 2 секунд с момента получения блокировки до завершения обработки

Так что проблема в том, что время от времени у меня будет происходить тайм-аут блокировки, и это через 30 секунд. Сначала я регистрируюсь, если запрос ожидает блокировки. Это выглядит так: 

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

А потом еще дальше по логам, я вижу это для того же запроса: 

"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."

Между ними 30 секунд. Запросы и любые данные о событии, связанные с ним, теряются в этот момент. Не хорошо для меня

Так что я подумал, посмотрю, достаточно ли быстро обрабатывается очередь. Я не уверен, как события поставлены в очередь <cflock>. Есть ли жесткий предел?

Во всяком случае, на этом конкретном пробеге я увидел, что:

  • Запрос перешел в очередь, когда там уже было 6 запросов, поэтому в очереди номер 7

  • В течение следующих 30 секунд из очереди удаляется около 17 запросов

  • Примерно столько же запросов добавляется в очередь

  • В этот период рассматриваемый запрос не обрабатывается и по истечении 30 секунд истекает

Я не могу поверить своим глазам! Это похоже на то, что очередь <cflock> обрабатывается не как «первым пришел - первым вышел» (FIFO), а как первым пришел последний - (FILO)!

Возможна ли такая вещь? Кто-нибудь еще видел такое поведение?

Большое спасибо заранее всем, у кого есть мысли.

Ciaran

Ответы [ 2 ]

2 голосов
/ 25 июня 2010

I думаю ключом является тот факт, что я использую шлюзы событий , которые являются асинхронными.Фактически после проведения эксперимента причина моей проблемы казалась очень очевидной :)

Я указал количество потоков, которые можно использовать для обработки запросов шлюза событий в CF admin (см. Раздел «Шлюз событий -> Настройки»).,В CF Dev Edition этот параметр равен 1, но в Enterprise Edition его можно увеличить.Я увеличил его до 5 для этого эксперимента.Вы видите это странное поведение только при увеличении.

Так что мой код шлюза событий очень прост, он просто создает UUID (чтобы я мог отслеживать запрос в моих журналах), а затем блокирует поток на 5секунды для имитации реальной обработки.Это sleep происходит внутри вызова cflock, поэтому только один поток может выполнить обработку одновременно.Нам нужно это, чтобы избежать обработки дубликатов в реальном коде.

Вот полный CFC: 

component {

    public void function onIncomingMessage (required struct msg) {

        var sys = createObject("java", "java.lang.System");
        var tag = createUUID();
        var logFile = "test\gatewaytest";

        writelog (file=logFile, text="#tag# - about to queue");

        try {

            lock name="myTestLock" timeout="120" {
                writelog (file=logFile, text="#tag# - got lock");

                thread action="sleep" duration="5000"; //ms 
            }

            writelog (file=logFile, text="#tag# - released lock");

        } catch (any e) {
            writelog (file=logFile, text="#tag# - ERROR - #e.message#");
        }
    }
}

Обратите внимание на очень длительное значение тайм-аута (2 минуты) на блокировке.Это связано с проблемой асинхронной обработки шлюза событий.

Шлюз событий - это простой встроенный тип CFML с идентификатором «TestGW», который я связываю с CFC выше.

Я настроил простой скрипт для отправки событий на событиешлюз, здесь это полностью: 

<cfset msg = {mymessage = "hello gateway"} />
<cfset sendGatewayMessage("TestGW", msg) />

СЦЕНАРИЙ 1 - ОДНА РЕЗЬБА:

Если число потоков обработки шлюза событий установлено в 1, и я фунтВ качестве шлюза я вижу следующий вывод журнала: 

"Information","Thread-17","06/25/10","10:32:09",,"50805BB4-1C23-9073-67A70A86CA6F8E54 - about to queue"
"Information","Thread-17","06/25/10","10:32:09",,"50805BB4-1C23-9073-67A70A86CA6F8E54 - got lock"
"Information","Thread-17","06/25/10","10:32:14",,"50805BB4-1C23-9073-67A70A86CA6F8E54 - released lock"
"Information","Thread-17","06/25/10","10:32:14",,"50811F1A-1C23-9073-67AD3E9C0BF2000C - about to queue"
"Information","Thread-17","06/25/10","10:32:14",,"50811F1A-1C23-9073-67AD3E9C0BF2000C - got lock"
"Information","Thread-17","06/25/10","10:32:19",,"50811F1A-1C23-9073-67AD3E9C0BF2000C - released lock"
"Information","Thread-17","06/25/10","10:32:19",,"5081E27F-1C23-9073-67B5D2EF6AED8426 - about to queue"
"Information","Thread-17","06/25/10","10:32:19",,"5081E27F-1C23-9073-67B5D2EF6AED8426 - got lock"
"Information","Thread-17","06/25/10","10:32:24",,"5081E27F-1C23-9073-67B5D2EF6AED8426 - released lock"
"Information","Thread-17","06/25/10","10:32:24",,"5082A5E1-1C23-9073-674E9467F395686F - about to queue"
"Information","Thread-17","06/25/10","10:32:24",,"5082A5E1-1C23-9073-674E9467F395686F - got lock"
"Information","Thread-17","06/25/10","10:32:29",,"5082A5E1-1C23-9073-674E9467F395686F - released lock"

Здесь важно отметить, что он однопоточный.Это все о очереди событий по одному, и все происходит в последовательности.

СЦЕНАРИЙ 2 - БОЛЬШЕ НИТЕЙ:

Если число потоков обработки шлюза событий увеличено до 5, и я набираю шлюз, я вижу следующий вывод журнала: 

"Information","Thread-18","06/25/10","11:26:01",,"526CC05B-C9E1-FADE-73CE3426BC0A3F92 - about to queue"
"Information","Thread-18","06/25/10","11:26:01",,"526CC05B-C9E1-FADE-73CE3426BC0A3F92 - got lock"
"Information","Thread-27","06/25/10","11:26:01",,"526CD0EB-049E-D382-2C3A7E3C0DBF8ED3 - about to queue"
"Information","Thread-21","06/25/10","11:26:02",,"526CDEED-C2B3-3C92-0F57CFA317AC02F8 - about to queue"
"Information","Thread-20","06/25/10","11:26:02",,"526CEE25-F25B-890C-F7501B5489C6BB21 - about to queue"
"Information","Thread-25","06/25/10","11:26:02",,"526CFD3C-EAFD-40E7-EBA2BE59B87D5936 - about to queue"
"Information","Thread-24","06/25/10","11:26:03",,"526D0FC5-E5E2-642E-452636C8838ADE33 - about to queue"
"Information","Thread-26","06/25/10","11:26:03",,"526D1096-C82E-535B-36D57D3A431D1436 - about to queue"
"Information","Thread-23","06/25/10","11:26:03",,"526D1F9C-9A9C-FA84-E153A944123E77BE - about to queue"
"Information","Thread-19","06/25/10","11:26:04",,"526D2EDC-EA54-4D83-3F6BB681A5CCAA89 - about to queue"
"Information","Thread-22","06/25/10","11:26:04",,"526D3F09-073F-2B0C-E94652D1C95B09CB - about to queue"
"Information","Thread-18","06/25/10","11:26:06",,"526CC05B-C9E1-FADE-73CE3426BC0A3F92 - released lock"
"Information","Thread-22","06/25/10","11:26:06",,"526D3F09-073F-2B0C-E94652D1C95B09CB - got lock"
"Information","Thread-22","06/25/10","11:26:11",,"526D3F09-073F-2B0C-E94652D1C95B09CB - released lock"
"Information","Thread-27","06/25/10","11:26:11",,"526CD0EB-049E-D382-2C3A7E3C0DBF8ED3 - got lock"
"Information","Thread-27","06/25/10","11:26:16",,"526CD0EB-049E-D382-2C3A7E3C0DBF8ED3 - released lock"
"Information","Thread-19","06/25/10","11:26:16",,"526D2EDC-EA54-4D83-3F6BB681A5CCAA89 - got lock"
"Information","Thread-19","06/25/10","11:26:21",,"526D2EDC-EA54-4D83-3F6BB681A5CCAA89 - released lock"

Обратите особое внимание на запрос с UUID 526D3F09-073F-2B0C-E94652D1C95B09CB.Это последний зарегистрированный запрос, поэтому он находится в конце очереди.Однако, как только блокировка становится доступной, прыгает и захватывает блокировку - , а не запрос 526CD0EB-049E-D382-2C3A7E3C0DBF8ED3, который был первым.

ЗАКЛЮЧЕНИЕ:

Поскольку при использовании более одного потока мы не можем гарантировать порядок обработки потоков при ожидании cflock при использовании шлюзов событий.Нам нужно убедиться, что значение тайм-аута для блокировки достаточно велико, чтобы в течение загруженного времени очередь событий могла быть обработана полностью, прежде чем какой-либо один запрос превысит тайм-аут блокировки.

Полагаю, это могло бы нам помочьза использование cflock с многопоточными шлюзами событий!

Я надеюсь, что это может помочь любому, кто столкнулся с этой проблемой.

Приветствия, Ciaran.

1 голос
/ 23 июня 2010

Я не уверен, что делать с вашей проблемой FIFO vs LIFO; но я могу предложить предложение для этого:

Между ними 30 секунд. Запросы и любые данные о событии, связанные с ним, теряются в этот момент. Не хорошо для меня.

Тег CFLock имеет атрибут с именем throwOnTimeout, который по умолчанию равен true. Если вы установите значение false, а не в случае возникновения исключения, в случае тайм-аута обработка пропустит заблокированный блок кода и продолжится в обычном режиме. Вы можете использовать это в своих интересах, например: 

<cfset made_it_through_lock = false />
<cflock name="single_threaded_lock_name" throwOnTimeout="false">
    <!--- ... do stuff ... --->
    <cfset made_it_through_lock = true />
</cflock>
<cfif made_it_through_lock eq false>
    <!--- 
          log the event data that you don't want to lose, then abort, 
          setting the necessary http status code & headers
    --->
</cfif>
...