Bulk insert into Hyperledger Fabric keeps timing out

Question

We're bulk inserting records into Hyperledger Fabric. However, we are hitting time out issue. Even we keep increasing the timeout, we will simply have this error happening at a later point.

Each transaction inserts 1000 records using PutState in a loop for all those records (blind insert, nothing in the read-set). We have also increased BatchTimeout to 3s and MaxMessageCount to 100, so that we get larger blocks (we see 4 transactions per block so 4000 [4x1000 records per transaction] records being inserted into ledger with every block).

When the bulk_update fails for CouchDB and the peer has to retry for each (of the 1000 records per transaction) records separately, the queries takes too long and overshoots the timeout. But this is our assumption. Also we found this : https://jira.hyperledger.org/browse/FAB-10558 , but it says it was already fixed in v1.2.0, which is the version we are using.

The error we got is net/http: request canceled (Client.Timeout exceeded while reading body) from the logs below:

We tried setting the following environment variable in the peer container:

CORE_CHAINCODE_EXECUTETIMEOUT=120s

And also req.setProposalWaitTime(120 * 1000) when using the Java SDK.

But then, we just get the same timeout error at a later point. So we can keep increasing timeout variable to a bigger number, but we believe it will happen again at a later point. Is the time required for inserting to CouchDB proportional to the number of records in CouchDB? Maybe updating the index will take more time when number of documents increase?

---

The runtime error log that we get (after 2-4 million or so records have been inserted) is as below:

    October 5th 2018, 04:36:38.646  github.com/hyperledger/fabric/core/committer.(*LedgerCommitter).CommitWithPvtData(0xc4222db8c0, 0xc451e4f470, 0xc4312ddd40, 0xdf8475800)
    October 5th 2018, 04:36:38.646  github.com/hyperledger/fabric/gossip/state.(*GossipStateProviderImpl).deliverPayloads(0xc4220c5a00)
    October 5th 2018, 04:36:38.646  goroutine 283 [running]:
    October 5th 2018, 04:36:38.646      /opt/gopath/src/github.com/hyperledger/fabric/core/committer/committer_impl.go:105 +0x6b
    October 5th 2018, 04:36:38.646      /opt/gopath/src/github.com/hyperledger/fabric/gossip/privdata/coordinator.go:236 +0xc3b
    October 5th 2018, 04:36:38.646      /opt/gopath/src/github.com/hyperledger/fabric/gossip/state/state.go:771 +0x6c
    October 5th 2018, 04:36:38.646  
    October 5th 2018, 04:36:38.646  github.com/hyperledger/fabric/core/ledger/kvledger.(*kvLedger).CommitWithPvtData(0xc421fb1860, 0xc451e4f470, 0x0, 0x0)
    October 5th 2018, 04:36:38.646  github.com/hyperledger/fabric/gossip/privdata.(*coordinator).StoreBlock(0xc422286e60, 0xc42462cd80, 0x0, 0x0, 0x0, 0xc4312dde78, 0x7329db)
    October 5th 2018, 04:36:38.646  github.com/hyperledger/fabric/gossip/state.(*GossipStateProviderImpl).commitBlock(0xc4220c5a00, 0xc42462cd80, 0x0, 0x0, 0x0, 0x0, 0x0)
    October 5th 2018, 04:36:38.646  panic: Error during commit to txmgr:net/http: request canceled (Client.Timeout exceeded while reading body)
    October 5th 2018, 04:36:38.646      /opt/gopath/src/github.com/hyperledger/fabric/core/ledger/kvledger/kv_ledger.go:273 +0x870
    October 5th 2018, 04:36:38.646      /opt/gopath/src/github.com/hyperledger/fabric/gossip/state/state.go:558 +0x3c5
    October 5th 2018, 04:36:38.646      /opt/gopath/src/github.com/hyperledger/fabric/gossip/state/state.go:239 +0x681
    October 5th 2018, 04:36:38.646  created by github.com/hyperledger/fabric/gossip/state.NewGossipStateProvider
    October 5th 2018, 04:36:03.645  2018-10-04 20:36:00.783 UTC [kvledger] CommitWithPvtData -> INFO 466e[0m Channel [mychannel]: Committed block [1719] with 4 transaction(s)
    October 5th 2018, 04:35:56.644  [33m2018-10-04 20:35:55.807 UTC [statecouchdb] commitUpdates -> WARN 465c[0m CouchDB batch document update encountered an problem. Retrying update for document ID:32216027-da66-4ecd-91a1-a37bdf47f07d
    October 5th 2018, 04:35:56.644  [33m2018-10-04 20:35:55.866 UTC [statecouchdb] commitUpdates -> WARN 4663[0m CouchDB batch document update encountered an problem. Retrying update for document ID:6eaed2ae-e5c4-48b1-b063-20eb3009969b
    October 5th 2018, 04:35:56.644  [33m2018-10-04 20:35:55.870 UTC [statecouchdb] commitUpdates -> WARN 4664[0m CouchDB batch document update encountered an problem. Retrying update for document ID:2ca2fbcc-e78f-4ed0-be70-2c4d7ecbee69
    October 5th 2018, 04:35:56.644  [33m2018-10-04 20:35:55.904 UTC [statecouchdb] commitUpdates -> WARN 4667[0m CouchDB batch document update encountered an problem. ... and so on

Answer 1

[33m2018-10-04 20:35:55.870 UTC [statecouchdb] commitUpdates -> WARN 4664[0m CouchDB batch document update encountered an problem. Retrying update for document ID:2ca2fbcc-e78f-4ed0-be70-2c4d7ecbee69

The above suggests that POST http://localhost:5984/db/_bulk_docks failed and so the individual documents were tried separately.

Looking at the different parameters available to configure, increasing requestTimeout under the ledger section might be worth a shot.

This can be done by setting the following environment variable in the docker-compose for your peer container :

CORE_LEDGER_STATE_COUCHDBCONFIG_REQUESTTIMEOUT=100s

The name of the environment variable associated to a configuration parameter can be derived by looking at this answer.

Configuring CORE_CHAINCODE_EXECUTETIMEOUT and proposalWaitime might not have had an effect as some other connection downstream (here it being the http connection between peer and couchdb) was timing out and then the timeout exception being propagated up.