Hazelcast OperationTimeoutException при удаленном выполнении - PullRequest
Новая
       19

Hazelcast OperationTimeoutException при удаленном выполнении

0 голосов
/ 04 июля 2019

Я использую 5-узловый кластер Hazelcast версии 3.6.6 в AWS.Я использую его в качестве распределителя рабочей нагрузки и использую API 

IExecutorService
<T> void submit(Runnable  task,
              MemberSelector memberSelector,
              ExecutionCallback<T> callback)

для выполнения задач на выбранном пользователем элементе.Я не использую балансировку на основе разделов, поскольку разные разделы будут иметь разные веса.

После запуска кластера он работает хорошо в течение нескольких дней, а затем отправляющие члены начинают получать OperationTimeoutException.Как только он начинается, все участники начинают получать этот тайм-аут, и это происходит довольно редко, может быть короткий период, когда все работает гладко, и затем это исключение начинает происходить снова.Целевой член получает задачу менее чем за секунду и выполняет ее правильно.Само исключение выглядит следующим образом:

3 июля 2019 г., 10:54:01 UTC:

Нет ответа в течение 560000 мс.Отмена вызова!Вызов {serviceName = 'hz: impl: executorService', op = com.hazelcast.executor.impl.operations.MemberCallableTaskOperation {identityHash = 1179024466, serviceName = 'hz: impl: executorService', partitionId = -1, replicaIndx = 0= 684145, invocationTime = 1562150679963 (ср. 03 июля 10:44:39 UTC 2019), waitTimeout = -1, callTimeout = 500000, name = exec_service_3}, partitionId = -1, replicaIndex = 0, tryCount = 250, tryPauseMillis = 500,invokeCount = 1, callTimeout = 500000, target = Address [xxxx]: 5701, backupsExpected = 0, backupsCompleted = 0, connection = Connection [/ xxxx: 5701 -> / xxxx: 35360], конечная точка = адрес [xxxx]: 5701,alive = true, type = MEMBER} Ответ не получен!ожидаемых резервных копий: 0 завершенных резервных копий: 0, выполнение заняло: 3445 миллисекунд

Stacktrace: 

at com.hazelcast.spi.impl.operationservice.impl.Invocation.newOperationTimeoutException(Invocation.java:536) ~[anodot-arnorld-1.0-SNAPSHOT.jar:na]
    at com.hazelcast.spi.impl.operationservice.impl.IsStillRunningService$IsOperationStillRunningCallback.setOperationTimeout(IsStillRunningService.java:241)
    at com.hazelcast.spi.impl.operationservice.impl.IsStillRunningService$IsOperationStillRunningCallback.onResponse(IsStillRunningService.java:229)
    at com.hazelcast.spi.impl.operationservice.impl.InvocationFuture$1.run(InvocationFuture.java:127)
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142) [na:1.8.0_121]
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
    at java.lang.Thread.run(Thread.java:745)
    at com.hazelcast.util.executor.HazelcastManagedThread.executeRun(HazelcastManagedThread.java:76) [anodot-arnorld-1.0-SNAPSHOT.jar:na]
    at com.hazelcast.util.executor.HazelcastManagedThread.run(HazelcastManagedThread.java:92)
    at ------ End remote and begin local stack-trace ------.(Unknown Source) ~[na:na]
    ... 8 frames truncated

Время возникновения исключения довольно странное: 

July 3rd 2019, 10:53:57.956 - task submitted for execution by sending instance
July 3rd 2019, 10:53:58.024 - execution starts on target instance
July 3rd 2019, 10:54:01.391 - the sending instance receives the exception

В моих журналах я вижу, что тайм-аут наступает вскоре после того, как задача была отправлена, и «исключение выполнения:» часть исключения является довольно точной, действительно, в указанном случае время, прошедшее с того момента, как задача была отправлена ​​на выполнениебыло около 3,5 секунд.С другой стороны, «invocationTime» (ср. Июл 03 10: 44: 39 UTC 2019) в указанном случае составляет около 10 минут назад в прошлом, даже дозадание было фактически передано на выполнение (3 июля 2019 г., 10:53:57 UTC)

Я видел, что это исключение связано с длинными GC-паузами, но, поскольку я постоянно отслеживаю GC, я совершенно уверенэто не вариант.Кроме того, взаимодействие между членами кластера выглядит вполне живым, задержки невелики.

Из того, что я видел в коде Hazelcast, invocationTime берется из "clusterClock", а не напрямую из системного времени, предполагая, что по какой-то причине часы кластера отключены на 10 минут, но яне могу понять, почему это происходит.Кластер довольно занят, но я не вижу каких-либо исключительных скачков нагрузки, когда это исключение начинает происходить.Проблема исчезает, когда я снимаю весь кластер, а затем запускаю его заново.Я планирую добавить мониторинг clusterTime, чтобы увидеть, когда он начнет дрейфовать, но он все равно не объяснит, почему это происходит.Есть мысли?

Обновление: Короче говоря, время кластера с течением времени отходит от системного времени, и как только разрыв становится достаточно большим, задачи начинают терпеть неудачу с исключением времени ожидания.Для деталей: https://github.com/hazelcast/hazelcast/issues/15339

...