Hello I created a Hyperledger Fabric network that works fine when I submit a few transaction proposals at a time, but since I have to do some benchmark tests I'm having errors when I send several proposals to peers with high send rate. The network has these elements:
- 3 Organizations
- 3 Peers (one for each Org)
- 1 Orderer
- 1 Channel
- 1 Java Chaincode compiled with fabric-chaincode-shim 1.4.4
- The endorsement policy for the chaincode requires positive replies from all peers to valide transactions
All run on a single machine with:
Intel i7-8750H CPU @ 2.20GHz
8 GB RAM DDR4
Ubuntu 19.04 with kernel 5.0.0-35-generic
Docker version 19.03.4
docker-compose version 1.21.0
Docker containers for peers and orderer use Fabric images at version 1.4.3, but I tried latest and the outcome is the same.
I use Hyperledger Caliper to submite proposals at high send rate, some of them are accepted by peers (the number varies between execution) but others failed with this error:
Transaction[901d0036b2] life-cycle errors:
Proposal response error by peer0.org1.com: transaction returned with failure: Failed to submit task for processing
I report here the piece of the peer's log with the error:
peer0.org1.com | 2019-11-25 21:14:56.723 UTC [peer.chaincode.dev-peer0.org1.com-mycontract-v0] func2 -> INFO 1439 21:14:56:720 FINE org.hyperledger.fabric.shim.impl.InnvocationTaskManager onChaincodeMessage [2b83c641] {
peer0.org1.com | 2019-11-25 21:14:56.723 UTC [peer.chaincode.dev-peer0.org1.com-mycontract-v0] func2 -> INFO 143a "type": "TRANSACTION",
peer0.org1.com | 2019-11-25 21:14:56.723 UTC [peer.chaincode.dev-peer0.org1.com-mycontract-v0] func2 -> INFO 143b "payload": "ChVpbml6aWFDb3JzYU1vYlN0YXRpY2EKCHBhc3F1YWxlCgp0cmVuaXRhbGlhCggxMTcwODM0MgoFMTM6MDAKBGF1dG8KFnBhcmNoZWdnaW9fZnVvcmlncm90dGEKA2duaQ==",
peer0.org1.com | 2019-11-25 21:14:56.723 UTC [peer.chaincode.dev-peer0.org1.com-mycontract-v0] func2 -> INFO 143c "txid": "2b83c641371573b49d7d88589404c14ac5b03fd14a1a7e538cdfb14359972a25",
peer0.org1.com | 2019-11-25 21:14:56.723 UTC [peer.chaincode.dev-peer0.org1.com-mycontract-v0] func2 -> INFO 143d "proposal": {
peer0.org1.com | 2019-11-25 21:14:56.723 UTC [peer.chaincode.dev-peer0.org1.com-mycontract-v0] func2 -> INFO 143e "proposalBytes": "CvkHCnUIAxABGgwI0Ijx7gUQgLnvogIiDGNvcnNlY2hhbm5lbCpAMmI4M2M2NDEzNzE1NzNiNDlkN2Q4ODU4OTQwNGMxNGFjNWIwM2ZkMTRhMWE3ZTUzOGNkZmIxNDM1OTk3MmEyNToREg8SDWNvcnNhY29udHJhY3QS/wYK4gYKDk9yZ0NpdGl6ZW5zTVNQEs8GLS0tLS1CRUdJTiBDRVJUSUZJQ0FURS0tLS0tCk1JSUNRekNDQWVtZ0F3SUJBZ0lRVkdPVVpQMElaRUhUTWJ4SSszUmJvREFLQmdncWhrak9QUVFEQWpDQmd6RUwKTUFrR0ExVUVCaE1DVlZNeEV6QVJCZ05WQkFnVENrTmhiR2xtYjNKdWFXRXhGakFVQmdOVkJBY1REVk5oYmlCRwpjbUZ1WTJselkyOHhJVEFmQmdOVkJBb1RHRzl5WjBOcGRHbDZaVzV6TG0xNWQyRjVNbWR2TG1OdmJURWtNQ0lHCkExVUVBeE1iWTJFdWIzSm5RMmwwYVhwbGJuTXViWGwzWVhreVoyOHVZMjl0TUI0WERURTVNVEF4TkRJek1EQXcKTUZvWERUSTVNVEF4TVRJek1EQXdNRm93ZERFTE1Ba0dBMVVFQmhNQ1ZWTXhFekFSQmdOVkJBZ1RDa05oYkdsbQpiM0p1YVdFeEZqQVVCZ05WQkFjVERWTmhiaUJHY21GdVkybHpZMjh4RHpBTkJnTlZCQXNUQm1Oc2FXVnVkREVuCk1DVUdBMVVFQXd3ZVZYTmxjakZBYjNKblEybDBhWHBsYm5NdWJYbDNZWGt5WjI4dVkyOXRNRmt3RXdZSEtvWkkKemowQ0FRWUlLb1pJemowREFRY0RRZ0FFd3JoZ0JlVXVPQVhDZmVVbGdKVG9YM053ckdraE1meHdUR0ZpRjFxcgp2YWRXR1c0VTBsUDlwdjg2cXVnelNXS3AzRTI0em5iNjNTWUdONHc0c2o0VVQ2Tk5NRXN3RGdZRFZSMFBBUUgvCkJBUURBZ2VBTUF3R0ExVWRFd0VCL3dRQ01BQXdLd1lEVlIwakJDUXdJb0FnaSszRHdteU9sTmtaa1BBbHZxcVoKWW5VeHpPU0puWVk3bU80WmRSSHR5a013Q2dZSUtvWkl6ajBFQXdJRFNBQXdSUUloQVBLSVlFcFhBbE9Ib05TNQpLNnlYQWxLb0FaM3VPYUlyWURxM1FrU1o0VlJkQWlCSWN0OUhCNFRNclhCU2V3K3ZuSzl3MUppOGt2NXFiaERDCmxzZlBrTWhxZnc9PQotLS0tLUVORCBDRVJUSUZJQ0FURS0tLS0tChIYnuHVxQX6OmrGPWoF3N6vpFLq18V1SGXOEnoKeAp2CAESDxINY29yc2Fjb250cmFjdBphChVpbml6aWFDb3JzYU1vYlN0YXRpY2EKCHBhc3F1YWxlCgp0cmVuaXRhbGlhCggxMTcwODM0MgoFMTM6MDAKBGF1dG8KFnBhcmNoZWdnaW9fZnVvcmlncm90dGEKA2duaQ==",
peer0.org1.com | 2019-11-25 21:14:56.723 UTC [peer.chaincode.dev-peer0.org1.com-mycontract-v0] func2 -> INFO 143f "signature": "MEUCIQDMAGTa6+CuBfav5v9+UsVo9vde5nMYIYbQpvDHgYrTRgIgeYseOCIm1CTwx3c8oIMVUkfVDt5nSvb6Ytd7x5lCtAk="
peer0.org1.com | 2019-11-25 21:14:56.723 UTC [peer.chaincode.dev-peer0.org1.com-mycontract-v0] func2 -> INFO 1440 },
peer0.org1.com | 2019-11-25 21:14:56.723 UTC [peer.chaincode.dev-peer0.org1.com-mycontract-v0] func2 -> INFO 1441 "channelId": "mychannel"
peer0.org1.com | 2019-11-25 21:14:56.723 UTC [peer.chaincode.dev-peer0.org1.com-mycontract-v0] func2 -> INFO 1442 }
peer0.org1.com | 2019-11-25 21:14:56.723 UTC [peer.chaincode.dev-peer0.org1.com-mycontract-v0] func2 -> INFO 1443 21:14:56:720 FINE org.hyperledger.fabric.shim.impl.InnvocationTaskManager handleMsg [2b83c641] Received TRANSACTION
peer0.org1.com | 2019-11-25 21:14:56.723 UTC [peer.chaincode.dev-peer0.org1.com-mycontract-v0] func2 -> INFO 1444 21:14:56:720 FINE org.hyperledger.fabric.shim.impl.InnvocationTaskManager newTask > newTask:created 2b83c641371573b49d7d88589404c14ac5b03fd14a1a7e538cdfb14359972a25
peer0.org1.com | 2019-11-25 21:14:56.723 UTC [peer.chaincode.dev-peer0.org1.com-mycontract-v0] func2 -> INFO 1445 21:14:56:721 FINE org.hyperledger.fabric.shim.impl.InnvocationTaskManager newTask > newTask:submitting 2b83c641371573b49d7d88589404c14ac5b03fd14a1a7e538cdfb14359972a25
peer0.org1.com | 2019-11-25 21:14:56.723 UTC [peer.chaincode.dev-peer0.org1.com-mycontract-v0] func2 -> INFO 1446 21:14:56:721 WARNING org.hyperledger.fabric.shim.impl.InnvocationTaskManager newTask Failed to submit task 2b83c641371573b49d7d88589404c14ac5b03fd14a1a7e538cdfb14359972a25Task java.util.concurrent.CompletableFuture$AsyncRun@39cf8f2a rejected from org.hyperledger.fabric.shim.impl.InnvocationTaskExecutor@e00a3e59[Running, pool size = 1, active threads = 1, queued tasks = 1, completed tasks = 15]
peer0.org1.com | 2019-11-25 21:14:56.723 UTC [peer.chaincode.dev-peer0.org1.com-mycontract-v0] func2 -> INFO 1447 java.util.concurrent.RejectedExecutionException: Task java.util.concurrent.CompletableFuture$AsyncRun@39cf8f2a rejected from org.hyperledger.fabric.shim.impl.InnvocationTaskExecutor@e00a3e59[Running, pool size = 1, active threads = 1, queued tasks = 1, completed tasks = 15]
peer0.org1.com | 2019-11-25 21:14:56.723 UTC [peer.chaincode.dev-peer0.org1.com-mycontract-v0] func2 -> INFO 1448 at java.util.concurrent.ThreadPoolExecutor$AbortPolicy.rejectedExecution(ThreadPoolExecutor.java:2063)
peer0.org1.com | 2019-11-25 21:14:56.723 UTC [peer.chaincode.dev-peer0.org1.com-mycontract-v0] func2 -> INFO 1449 at java.util.concurrent.ThreadPoolExecutor.reject(ThreadPoolExecutor.java:830)
peer0.org1.com | 2019-11-25 21:14:56.723 UTC [peer.chaincode.dev-peer0.org1.com-mycontract-v0] func2 -> INFO 144a at java.util.concurrent.ThreadPoolExecutor.execute(ThreadPoolExecutor.java:1379)
peer0.org1.com | 2019-11-25 21:14:56.723 UTC [peer.chaincode.dev-peer0.org1.com-mycontract-v0] func2 -> INFO 144b at java.util.concurrent.CompletableFuture.asyncRunStage(CompletableFuture.java:1640)
peer0.org1.com | 2019-11-25 21:14:56.723 UTC [peer.chaincode.dev-peer0.org1.com-mycontract-v0] func2 -> INFO 144c at java.util.concurrent.CompletableFuture.runAsync(CompletableFuture.java:1858)
peer0.org1.com | 2019-11-25 21:14:56.723 UTC [peer.chaincode.dev-peer0.org1.com-mycontract-v0] func2 -> INFO 144d at org.hyperledger.fabric.shim.impl.InnvocationTaskManager.newTask(InnvocationTaskManager.java:226)
peer0.org1.com | 2019-11-25 21:14:56.723 UTC [peer.chaincode.dev-peer0.org1.com-mycontract-v0] func2 -> INFO 144e at org.hyperledger.fabric.shim.impl.InnvocationTaskManager.handleMsg(InnvocationTaskManager.java:172)
peer0.org1.com | 2019-11-25 21:14:56.723 UTC [peer.chaincode.dev-peer0.org1.com-mycontract-v0] func2 -> INFO 144f at org.hyperledger.fabric.shim.impl.InnvocationTaskManager.onChaincodeMessage(InnvocationTaskManager.java:141)
peer0.org1.com | 2019-11-25 21:14:56.723 UTC [peer.chaincode.dev-peer0.org1.com-mycontract-v0] func2 -> INFO 1450 at org.hyperledger.fabric.shim.impl.ChaincodeSupportClient$$Lambda$148.0000000094ECAD00.accept(Unknown Source)
peer0.org1.com | 2019-11-25 21:14:56.723 UTC [peer.chaincode.dev-peer0.org1.com-mycontract-v0] func2 -> INFO 1451 at org.hyperledger.fabric.shim.impl.ChaincodeSupportClient$1.onNext(ChaincodeSupportClient.java:86)
peer0.org1.com | 2019-11-25 21:14:56.723 UTC [peer.chaincode.dev-peer0.org1.com-mycontract-v0] func2 -> INFO 1452 at org.hyperledger.fabric.shim.impl.ChaincodeSupportClient$1.onNext(ChaincodeSupportClient.java:82)
peer0.org1.com | 2019-11-25 21:14:56.723 UTC [peer.chaincode.dev-peer0.org1.com-mycontract-v0] func2 -> INFO 1453 at io.grpc.stub.ClientCalls$StreamObserverToCallListenerAdapter.onMessage(ClientCalls.java:429)
peer0.org1.com | 2019-11-25 21:14:56.723 UTC [peer.chaincode.dev-peer0.org1.com-mycontract-v0] func2 -> INFO 1454 at io.grpc.ForwardingClientCallListener.onMessage(ForwardingClientCallListener.java:33)
peer0.org1.com | 2019-11-25 21:14:56.723 UTC [peer.chaincode.dev-peer0.org1.com-mycontract-v0] func2 -> INFO 1455 at io.grpc.ForwardingClientCallListener.onMessage(ForwardingClientCallListener.java:33)
peer0.org1.com | 2019-11-25 21:14:56.723 UTC [peer.chaincode.dev-peer0.org1.com-mycontract-v0] func2 -> INFO 1456 at io.grpc.internal.ClientCallImpl$ClientStreamListenerImpl$1MessagesAvailable.runInternal(ClientCallImpl.java:599)
peer0.org1.com | 2019-11-25 21:14:56.723 UTC [peer.chaincode.dev-peer0.org1.com-mycontract-v0] func2 -> INFO 1457 at io.grpc.internal.ClientCallImpl$ClientStreamListenerImpl$1MessagesAvailable.runInContext(ClientCallImpl.java:584)
peer0.org1.com | 2019-11-25 21:14:56.723 UTC [peer.chaincode.dev-peer0.org1.com-mycontract-v0] func2 -> INFO 1458 at io.grpc.internal.ContextRunnable.run(ContextRunnable.java:37)
peer0.org1.com | 2019-11-25 21:14:56.723 UTC [peer.chaincode.dev-peer0.org1.com-mycontract-v0] func2 -> INFO 1459 at io.grpc.internal.SerializingExecutor.run(SerializingExecutor.java:123)
peer0.org1.com | 2019-11-25 21:14:56.723 UTC [endorser] callChaincode -> INFO 145a [mychannel][2b83c641] Exit chaincode: name:"mycontract" (93ms)
peer0.org1.com | 2019-11-25 21:14:56.723 UTC [peer.chaincode.dev-peer0.org1.com-mycontract-v0] func2 -> INFO 145b at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
peer0.org1.com | 2019-11-25 21:14:56.723 UTC [peer.chaincode.dev-peer0.org1.com-mycontract-v0] func2 -> INFO 145c at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
peer0.org1.com | 2019-11-25 21:14:56.723 UTC [peer.chaincode.dev-peer0.org1.com-mycontract-v0] func2 -> INFO 145d at java.lang.Thread.run(Thread.java:819)
peer0.org1.com | 2019-11-25 21:14:56.723 UTC [peer.chaincode.dev-peer0.org1.com-mycontract-v0] func2 -> INFO 145e
peer0.org1.com | 2019-11-25 21:14:56.723 UTC [peer.chaincode.dev-peer0.org1.com-mycontract-v0] func2 -> INFO 145f 21:14:56:722 FINE org.hyperledger.fabric.shim.impl.ChaincodeSupportClient$2 accept > sendToPeer 2b83c641371573b49d7d88589404c14ac5b03fd14a1a7e538cdfb14359972a25
peer0.org1.com | 2019-11-25 21:14:56.723 UTC [peer.chaincode.dev-peer0.org1.com-mycontract-v0] func2 -> INFO 1460 21:14:56:722 FINE org.hyperledger.fabric.shim.impl.ChaincodeSupportClient$2 accept < sendToPeer 2b83c641371573b49d7d88589404c14ac5b03fd14a1a7e538cdfb14359972a25
peer0.org1.com | 2019-11-25 21:14:56.723 UTC [endorser] SimulateProposal -> ERRO 1461 [mychannel][2b83c641] failed to invoke chaincode name:"mycontract" , error: transaction returned with failure: Failed to submit task for processing
peer0.org1.com | github.com/hyperledger/fabric/core/chaincode.processChaincodeExecutionResult
peer0.org1.com | /opt/gopath/src/github.com/hyperledger/fabric/core/chaincode/chaincode_support.go:266
peer0.org1.com | github.com/hyperledger/fabric/core/chaincode.(*ChaincodeSupport).Execute
peer0.org1.com | /opt/gopath/src/github.com/hyperledger/fabric/core/chaincode/chaincode_support.go:240
peer0.org1.com | github.com/hyperledger/fabric/core/endorser.(*SupportImpl).Execute
peer0.org1.com | /opt/gopath/src/github.com/hyperledger/fabric/core/endorser/support.go:147
peer0.org1.com | github.com/hyperledger/fabric/core/endorser.(*Endorser).callChaincode
peer0.org1.com | /opt/gopath/src/github.com/hyperledger/fabric/core/endorser/endorser.go:146
peer0.org1.com | github.com/hyperledger/fabric/core/endorser.(*Endorser).SimulateProposal
peer0.org1.com | /opt/gopath/src/github.com/hyperledger/fabric/core/endorser/endorser.go:247
peer0.org1.com | github.com/hyperledger/fabric/core/endorser.(*Endorser).ProcessProposal
peer0.org1.com | /opt/gopath/src/github.com/hyperledger/fabric/core/endorser/endorser.go:500
peer0.org1.com | github.com/hyperledger/fabric/core/handlers/auth/filter.(*expirationCheckFilter).ProcessProposal
peer0.org1.com | /opt/gopath/src/github.com/hyperledger/fabric/core/handlers/auth/filter/expiration.go:61
peer0.org1.com | github.com/hyperledger/fabric/core/handlers/auth/filter.(*filter).ProcessProposal
peer0.org1.com | /opt/gopath/src/github.com/hyperledger/fabric/core/handlers/auth/filter/filter.go:32
peer0.org1.com | github.com/hyperledger/fabric/protos/peer._Endorser_ProcessProposal_Handler.func1
peer0.org1.com | /opt/gopath/src/github.com/hyperledger/fabric/protos/peer/peer.pb.go:169
peer0.org1.com | github.com/hyperledger/fabric/vendor/github.com/grpc-ecosystem/go-grpc-middleware.ChainUnaryServer.func1.1
peer0.org1.com | /opt/gopath/src/github.com/hyperledger/fabric/vendor/github.com/grpc-ecosystem/go-grpc-middleware/chain.go:31
peer0.org1.com | github.com/hyperledger/fabric/core/comm.(*Throttle).UnaryServerIntercptor
peer0.org1.com | /opt/gopath/src/github.com/hyperledger/fabric/core/comm/throttle.go:54
peer0.org1.com | github.com/hyperledger/fabric/vendor/github.com/grpc-ecosystem/go-grpc-middleware.ChainUnaryServer.func1.1
peer0.org1.com | /opt/gopath/src/github.com/hyperledger/fabric/vendor/github.com/grpc-ecosystem/go-grpc-middleware/chain.go:34
peer0.org1.com | github.com/hyperledger/fabric/common/grpclogging.UnaryServerInterceptor.func1
peer0.org1.com | /opt/gopath/src/github.com/hyperledger/fabric/common/grpclogging/server.go:91
peer0.org1.com | github.com/hyperledger/fabric/vendor/github.com/grpc-ecosystem/go-grpc-middleware.ChainUnaryServer.func1.1
peer0.org1.com | /opt/gopath/src/github.com/hyperledger/fabric/vendor/github.com/grpc-ecosystem/go-grpc-middleware/chain.go:34
peer0.org1.com | github.com/hyperledger/fabric/common/grpcmetrics.UnaryServerInterceptor.func1
peer0.org1.com | /opt/gopath/src/github.com/hyperledger/fabric/common/grpcmetrics/interceptor.go:30
peer0.org1.com | github.com/hyperledger/fabric/vendor/github.com/grpc-ecosystem/go-grpc-middleware.ChainUnaryServer.func1
peer0.org1.com | /opt/gopath/src/github.com/hyperledger/fabric/vendor/github.com/grpc-ecosystem/go-grpc-middleware/chain.go:39
peer0.org1.com | github.com/hyperledger/fabric/protos/peer._Endorser_ProcessProposal_Handler
peer0.org1.com | /opt/gopath/src/github.com/hyperledger/fabric/protos/peer/peer.pb.go:171
peer0.org1.com | github.com/hyperledger/fabric/vendor/google.golang.org/grpc.(*Server).processUnaryRPC
peer0.org1.com | /opt/gopath/src/github.com/hyperledger/fabric/vendor/google.golang.org/grpc/server.go:982
peer0.org1.com | github.com/hyperledger/fabric/vendor/google.golang.org/grpc.(*Server).handleStream
peer0.org1.com | /opt/gopath/src/github.com/hyperledger/fabric/vendor/google.golang.org/grpc/server.go:1208
peer0.org1.com | github.com/hyperledger/fabric/vendor/google.golang.org/grpc.(*Server).serveStreams.func1.1
peer0.org1.com | /opt/gopath/src/github.com/hyperledger/fabric/vendor/google.golang.org/grpc/server.go:686
peer0.org1.com | runtime.goexit
peer0.org1.com | /opt/go/src/runtime/asm_amd64.s:1337
peer0.org1.com | 2019-11-25 21:14:56.724 UTC [comm.grpc.server] 1 -> INFO 1462 unary call completed grpc.service=protos.Endorser grpc.method=ProcessProposal grpc.peer_address=172.18.0.1:34430 grpc.code=OK grpc.call_duration=96.086094ms
As the message INFO 1447 suggests the peer fails to create a new task for the proposal, probably because many requests arrive together. Is this consideration correct? Is there any way to change the maximum number of parallel tasks that a peer can create? Because this situation happens even with a rate of 100 rps and I think I can push performances further.
SOLUTION
As reported on this link:
https://jira.hyperledger.org/browse/FAB-17110
When Java chaincodes are compiled with fabric-chaincode-shim at version 1.4.4 the default thread pool is set too low, using the workaround described on the link I changed the pool queue size to decrease discarded transactions under high load conditions.
Thanks to david_k for the reply.
