Corda RPC通信。性能缓慢。

Question

当客户端通过RPC触发cordapp并等待结果时，会出现这样的情况。

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

流触发器正确执行并返回响应，但在处理完流程后响应速度慢是个问题。在FlowLogic.call()代码块的末尾，响应应通过Artemis消息返回给客户端。12秒后，结果通过Corda future返回给客户端。

在客户端上，可以使用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 - 流程开始，消耗1k个对象
• 12:12:58.603 OnNext [B@2dceac3d] - 操作的实际结果。 因此，返回响应需要大约12.5秒。

根据Jprofiler Corda的处理时间大约为1.3秒，并发送结果。

这种行为的原因可能是Artemis消息的日志记录速度较慢？

更新： 发现Corda有一个暂停/恢复机制（检查点），可以将线程状态存储到磁盘中，并在未来再次读取它并恢复此线程。 net.corda.node.services.statemachine.FlowStateMachineImpl#run 触发co.paralleluniverse.fibers.Fiber#parkAndSerialize。似乎这是其中一个时间较长的部分。

非常感谢您的帮助！

- Oleksandr Abasov

Answer 1

可能有多种原因：

1. JProfiler 可能没有正确报告流程持续时间。其他性能分析工具肯定会在 Fibers 的暂停中遇到困难，因为每次从挂起中恢复看起来都像是一个不同的方法调用。我建议您向您的流程添加一些日志，以检查它实际上需要多长时间。
2. 如果您从流程返回一个非常大的结果（例如大量的大型对象），那么该结果在 RPC 上的序列化和反序列化可能需要相当长的时间。所以您是否返回了一个大的结果？

- Rick Parker

---

嗨Rick， 2. 不，结果只是关于这些对象的元信息，它们是如何被一般处理的。与输入Json消息大小相比，输入为2MB，输出为约800B。 - Oleksandr Abasov

在此处提交了一个工单，并提供了详细的日志：https://r3-cev.atlassian.net/servicedesk/customer/portal/2/SUP-1084 - Oleksandr Abasov

Answer 2

找到了延迟的根本原因，似乎所有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包含PCAssetBatchItem列表列，似乎Hibernate会逐个持久化它们而不是使用批处理。 通过修复代码中的这部分，延迟问题得到了解决。

- Oleksandr Abasov