Corda RPC 通信。性能缓慢

Question

有一个场景，客户端通过RPC触发cordapp并等待结果。

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

流程正确触发并return响应，但处理流程后响应缓慢的问题。在 FlowLogic.call() 代码块的末尾，响应应该通过 Artemis 消息返回给客户端。 12 秒后，结果 return 通过 Corda Future 返回客户端。

在客户端调试 RPCClientProxyHandler 的 lvl 日志以检查进程如何工作：

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 - 消耗 1k 个对象的流的开始
12:12:58.603 OnNext [B@2dceac3d] - 操作的实际结果。所以 return 响应时间约为 12.5 秒。

根据 Jprofiler，Corda 在 ~1.3 秒内处理了流程并将结果发回。

这种行为的原因是什么，artemis 消息的日志记录速度很慢？

更新：发现Corda有一个suspend/resume机制（checkpoints），将线程状态存储到Disk中，以后再读取再恢复这个线程。 net.corda.node.services.statemachine.FlowStateMachineImpl#运行触发 co.paralleluniverse.fibers.Fiber#parkAndSerialize。看来是时间消费者之一。

非常感谢您

Answer 1

可能有多种原因：

JProfiler 可能无法正确报告流持续时间。其他分析工具肯定难以像 Fibers 那样进行停放，因为每次从挂起恢复看起来都像是一个不同的方法调用。我会在您的流程中添加一些日志记录，以检查实际需要多长时间。
如果您 return 从您的流中获得非常大的结果（例如，大型对象的大量集合），则通过 RPC 对其进行序列化和反序列化可能需要相当长的时间。那么，您 return 的结果大吗？

Answer 2

找到了延迟的根本原因，似乎所有的entityManager事务都在流程结束时刷新，但并没有像我预期的那样在withEntityManager块结束后刷新

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

我花了一段时间才明白，日志的原因我认为数据是持久化的。这是因为带有 OneToMany 注释的实体 PCAssetBatch 包含 PCAssetBatchItem 的列列表，似乎 hibernate 不是通过使用批处理将它们一一保存。通过修复这部分代码解决了延迟问题。

Corda RPC 通信。性能缓慢

Corda RPC communication. Slow Performance

rpc

corda

activemq-artemis