Связь Corda RPC. Медленная производительность

Есть сценарий, когда клиент запускает cordapp через RPC и ждет результата.

rpcConnection.proxy
.startFlow(::ImportAssetFlow, importDto)
.returnValue
.get(importTimeout /* 30000 ms */, TimeUnit.MILLISECONDS)

Поток срабатывает правильно и возвращает ответ, но проблема с медленным откликом после обработки потока. В конце кодового блока FlowLogic.call () ответ должен быть возвращен клиенту через сообщение Artemis. Результат возвращается клиенту через будущее Corda через 12 секунд.

На стороне клиента в журнале lvl отладки RPCClientProxyHandler, чтобы проверить, как работает процесс:

2020-01-08 12:12:45.982 DEBUG [,,,] 78798 --- [global-threads)] n.c.c.r.internal.RPCClientProxyHandler   : Got message from RPC server RpcReply(id=fc317c4a-3de4-4936-b4c3-768b8b727245, timestamp: 2020-01-08T10:12:44.237Z, entityType: Invocation, result=Success(FlowHandleImpl(id=[16566124-f7d2-41cf-b3a4-f86846073632], returnValue=net.corda.core.internal.concurrent.CordaFutureImpl@58f8aa01)), deduplicationIdentity=e3f6d696-dea4-45b0-95b8-f9c0fe363a9f)
2020-01-08 12:12:45.986 DEBUG [,,,] 78798 --- [global-threads)] n.c.c.r.internal.RPCClientProxyHandler   : Got message from RPC server Observation(id=b3f0b064-6d82-4900-85e6-e70b7d00926a, timestamp: 2020-01-08T10:11:26.411Z, entityType: Invocation, content=[rx.Notification@b461fac0 OnNext Added(stateMachineInfo=StateMachineInfo([16566124-f7d2-41cf-b3a4-f86846073632], ***.workflow.asset.flow.ImportAssetFlow))], deduplicationIdentity=e3f6d696-dea4-45b0-95b8-f9c0fe363a9f)
2020-01-08 12:12:45.987 DEBUG [,,,] 78798 --- [global-threads)] n.c.c.r.internal.RPCClientProxyHandler   : Got message from RPC server Observation(id=12887a04-f22c-422d-b684-c679f137d66b, timestamp: 2020-01-08T10:12:45.979Z, entityType: Invocation, content=[rx.Notification@4c59250 OnNext Starting], deduplicationIdentity=e3f6d696-dea4-45b0-95b8-f9c0fe363a9f)
2020-01-08 12:12:58.603 DEBUG [,,,] 78798 --- [global-threads)] n.c.c.r.internal.RPCClientProxyHandler   : Got message from RPC server Observation(id=b83c15ca-9047-4958-a106-65165e5abfbd, timestamp: 2020-01-08T10:12:45.975Z, entityType: Invocation, content=[rx.Notification@e03cfa2d OnNext [B@2dceac3d], deduplicationIdentity=e3f6d696-dea4-45b0-95b8-f9c0fe363a9f)
2020-01-08 12:12:58.605 DEBUG [,,,] 78798 --- [global-threads)] n.c.c.r.internal.RPCClientProxyHandler   : Got message from RPC server Observation(id=b83c15ca-9047-4958-a106-65165e5abfbd, timestamp: 2020-01-08T10:12:45.975Z, entityType: Invocation, content=[rx.Notification@15895539 OnCompleted], deduplicationIdentity=e3f6d696-dea4-45b0-95b8-f9c0fe363a9f)

Между событиями большой разрыв

  • 12:12:45.987 OnNext Starting - начало потока, потребляющего 1к объектов
  • 12:12:58.603 OnNext [B@2dceac3d] - фактический результат операции. Таким образом, время возврата ответа составляет ~ 12,5 с.

Согласно Jprofiler, Corda обработала поток за ~ 1,3 секунды и отправила результат обратно. Звонки треда Corda

Что может быть причиной такого поведения, медленного ведения журнала сообщений Artemis?

UPD: обнаружено, что Corda имеет механизм приостановки / возобновления (контрольные точки), чтобы сохранить состояние потока на Диск и в будущем прочитать его снова и возобновить этот поток. net.corda.node.services.statemachine.FlowStateMachineImpl # запускает запуск co.paralleluniverse.fibers.Fiber # parkAndSerialize. Кажется, это один из потребителей времени.

Заранее большое спасибо


corda activemq-artemis rpc
person Oleksandr Abasov    schedule 08.01.2020    source источник

Ответы (2)


arrow_upward
0
arrow_downward

Причин может быть несколько:

  1. JProfiler может неправильно сообщать продолжительность потока. Другие инструменты профилирования, безусловно, испытывают трудности с парковкой, которую делают Fibers, поскольку каждое возобновление из приостановки выглядит как отдельный вызов метода. Я бы добавил в ваш поток запись, чтобы проверить, сколько времени это действительно займет.
  2. Если вы возвращаете действительно большой результат из своего потока (например, большую коллекцию больших объектов), сериализация и десериализация этого через RPC может занять разумное количество времени. Так вы возвращаете большой результат?
person Rick Parker    schedule 21.01.2020
comment
Привет, Рик, 2. Нет, результат - это просто метаинформация об этих объектах, как они вообще обрабатывались. По сравнению с размером входного сообщения Json, размер входных данных составляет 2 МБ, а выходных данных составляет ~ 800 ГБ. - person Oleksandr Abasov; 22.01.2020
comment
поднял заявку здесь с подробными журналами: r3-cev. atlassian.net/servicedesk/customer/portal/2/SUP-1084 - person Oleksandr Abasov; 22.01.2020

arrow_upward
0
arrow_downward

Обнаружена основная причина задержки, похоже, что все транзакции entityManager сбрасываются в конце потока, но не после окончания блока с EntityManager, как я ожидал

fun save(assetBatch: PCAssetBatch): PCAssetBatch {
    return serviceHub.withEntityManager {
        persist(assetBatch)
        logger.debug("Batch [${assetBatch.batchId} - ${assetBatch.batchName}] has been persisted")
        assetBatch
    }
}

Потребовалось время, чтобы понять это, из-за журнала я считал, что данные сохранились. Это из-за того, что объект с аннотацией OneToMany PCAssetBatch содержит столбец List из PCAssetBatchItem, кажется, что спящий режим сохраняет их один за другим без использования пакетной обработки. Задержка была устранена путем исправления этой части кода.

person Oleksandr Abasov    schedule 23.01.2020