search

hyperledger / caliper

A blockchain benchmark framework to measure performance of multiple blockchain solutions https://wiki.hyperledger.org/display/caliper
https://hyperledger.github.io/caliper/
Apache License 2.0
651 stars 404 forks source link

caliper makes no progress when the tps is relatively high #1510

Closed javenleee closed 8 months ago

javenleee commented 8 months ago

Which Caliper version are you using?

0.5.0

Which Node.JS version are you using?

v16.20.2

Which operating system are you using?

Ubuntu 20.04

Please provide some context for your error. For example, when did the error occur? What were you trying to achieve, and how?

I'm conducting performance testing on my Hyperledger Fabric network using Caliper. However, I encountered the following issue when the transactions per second (TPS) reached a relatively high level, around 110:

2024.01.15-17:12:02.454 error [caliper] [connectors/v2/FabricGateway]   Failed to perform submit transaction [changeCarOwner] using arguments [Client3_CAR,Michel],  with error: TransactionError: Commit of transaction f3717ca571f87eaa611edcf1a147fc987bd5cd71f0b3ea26f6b15da615f8015b failed on peer peer0.org1.example.com:7051 with status MVCC_READ_CONFLICT
    at TransactionEventHandler.eventCallback (/home/javen/go/src/github.com/hyperledger/caliper-benchmarks/node_modules/fabric-network/lib/impl/event/transactioneventhandler.js:105:31)
    at CommitListenerSession.notifyListener (/home/javen/go/src/github.com/hyperledger/caliper-benchmarks/node_modules/fabric-network/lib/impl/event/commitlistenersession.js:97:18)
    at EventListener.callback (/home/javen/go/src/github.com/hyperledger/caliper-benchmarks/node_modules/fabric-network/lib/impl/event/commitlistenersession.js:88:18)
    at EventListener.onEvent (/home/javen/go/src/github.com/hyperledger/caliper-benchmarks/node_modules/fabric-common/lib/EventListener.js:124:10)
    at EventService._callTransactionListener (/home/javen/go/src/github.com/hyperledger/caliper-benchmarks/node_modules/fabric-common/lib/EventService.js:1051:16)
    at EventService._processTxEvents (/home/javen/go/src/github.com/hyperledger/caliper-benchmarks/node_modules/fabric-common/lib/EventService.js:1006:12)
    at ClientDuplexStreamImpl.<anonymous> (/home/javen/go/src/github.com/hyperledger/caliper-benchmarks/node_modules/fabric-common/lib/EventService.js:481:12)
    at ClientDuplexStreamImpl.emit (node:events:513:28)
    at addChunk (node:internal/streams/readable:315:12)
    at readableAddChunk (node:internal/streams/readable:289:9)
2024.01.15-17:12:03.456 info  [caliper] [connectors/v2/FabricGateway]   disconnecting gateway for user User1
2024.01.15-17:12:03.458 info  [caliper] [connectors/v2/FabricGateway]   disconnecting gateway for user User1
2024.01.15-17:12:03.459 info  [caliper] [worker-message-handler]    Worker#3 finished Round#1
2024.01.15-17:12:03.459 info  [caliper] [worker-message-handler]    Worker#4 finished Round#1
2024.01.15-17:12:07.346 info  [caliper] [default-observer]  Resetting txCount indicator count
2024.01.15-17:12:12.350 info  [caliper] [default-observer]  [Change car owner. Round 1 Transaction Info] - Submitted: 0 Succ: 0 Fail:0 Unfinished:0
2024.01.15-17:12:17.355 info  [caliper] [default-observer]  [Change car owner. Round 1 Transaction Info] - Submitted: 0 Succ: 0 Fail:0 Unfinished:0
2024.01.15-17:12:22.360 info  [caliper] [default-observer]  [Change car owner. Round 1 Transaction Info] - Submitted: 0 Succ: 0 Fail:0 Unfinished:0
2024.01.15-17:12:27.365 info  [caliper] [default-observer]  [Change car owner. Round 1 Transaction Info] - Submitted: 0 Succ: 0 Fail:0 Unfinished:0
2024.01.15-17:12:32.370 info  [caliper] [default-observer]  [Change car owner. Round 1 Transaction Info] - Submitted: 0 Succ: 0 Fail:0 Unfinished:0
2024.01.15-17:12:37.375 info  [caliper] [default-observer]  [Change car owner. Round 1 Transaction Info] - Submitted: 0 Succ: 0 Fail:0 Unfinished:0
2024.01.15-17:12:42.381 info  [caliper] [default-observer]  [Change car owner. Round 1 Transaction Info] - Submitted: 0 Succ: 0 Fail:0 Unfinished:0
2024.01.15-17:12:47.386 info  [caliper] [default-observer]  [Change car owner. Round 1 Transaction Info] - Submitted: 0 Succ: 0 Fail:0 Unfinished:0
2024.01.15-17:12:52.391 info  [caliper] [default-observer]  [Change car owner. Round 1 Transaction Info] - Submitted: 0 Succ: 0 Fail:0 Unfinished:0
2024.01.15-17:12:57.395 info  [caliper] [default-observer]  [Change car owner. Round 1 Transaction Info] - Submitted: 0 Succ: 0 Fail:0 Unfinished:0
2024.01.15-17:13:02.400 info  [caliper] [default-observer]  [Change car owner. Round 1 Transaction Info] - Submitted: 0 Succ: 0 Fail:0 Unfinished:0
2024.01.15-17:13:07.405 info  [caliper] [default-observer]  [Change car owner. Round 1 Transaction Info] - Submitted: 0 Succ: 0 Fail:0 Unfinished:0
2024.01.15-17:13:12.410 info  [caliper] [default-observer]  [Change car owner. Round 1 Transaction Info] - Submitted: 0 Succ: 0 Fail:0 Unfinished:0
2024.01.15-17:13:17.415 info  [caliper] [default-observer]  [Change car owner. Round 1 Transaction Info] - Submitted: 0 Succ: 0 Fail:0 Unfinished:0
2024.01.15-17:13:22.420 info  [caliper] [default-observer]  [Change car owner. Round 1 Transaction Info] - Submitted: 0 Succ: 0 Fail:0 Unfinished:0
2024.01.15-17:13:27.425 info  [caliper] [default-observer]  [Change car owner. Round 1 Transaction Info] - Submitted: 0 Succ: 0 Fail:0 Unfinished:0
2024.01.15-17:13:32.430 info  [caliper] [default-observer]  [Change car owner. Round 1 Transaction Info] - Submitted: 0 Succ: 0 Fail:0 Unfinished:0
2024.01.15-17:13:37.435 info  [caliper] [default-observer]  [Change car owner. Round 1 Transaction Info] - Submitted: 0 Succ: 0 Fail:0 Unfinished:0
...

actually, in my orderer's log, there are 808 tx(it is 1000 in my config file) it has ordered. so i think there are still about 200 tx which has not been launched and the caliper is just stuck here

What was the observed incorrect behavior?

The logs persistently display the same content:

2024.01.15-17:13:37.435 info  [caliper] [default-observer]  [Change car owner. Round 1 Transaction Info] - Submitted: 0 Succ: 0 Fail:0 Unfinished:0

with no signs of progress.

Please provide the error logs and their surroundings.

2024.01.15-17:12:02.454 error [caliper] [connectors/v2/FabricGateway]   Failed to perform submit transaction [changeCarOwner] using arguments [Client3_CAR,Michel],  with error: TransactionError: Commit of transaction f3717ca571f87eaa611edcf1a147fc987bd5cd71f0b3ea26f6b15da615f8015b failed on peer peer0.org1.example.com:7051 with status MVCC_READ_CONFLICT
    at TransactionEventHandler.eventCallback (/home/javen/go/src/github.com/hyperledger/caliper-benchmarks/node_modules/fabric-network/lib/impl/event/transactioneventhandler.js:105:31)
    at CommitListenerSession.notifyListener (/home/javen/go/src/github.com/hyperledger/caliper-benchmarks/node_modules/fabric-network/lib/impl/event/commitlistenersession.js:97:18)
    at EventListener.callback (/home/javen/go/src/github.com/hyperledger/caliper-benchmarks/node_modules/fabric-network/lib/impl/event/commitlistenersession.js:88:18)
    at EventListener.onEvent (/home/javen/go/src/github.com/hyperledger/caliper-benchmarks/node_modules/fabric-common/lib/EventListener.js:124:10)
    at EventService._callTransactionListener (/home/javen/go/src/github.com/hyperledger/caliper-benchmarks/node_modules/fabric-common/lib/EventService.js:1051:16)
    at EventService._processTxEvents (/home/javen/go/src/github.com/hyperledger/caliper-benchmarks/node_modules/fabric-common/lib/EventService.js:1006:12)
    at ClientDuplexStreamImpl.<anonymous> (/home/javen/go/src/github.com/hyperledger/caliper-benchmarks/node_modules/fabric-common/lib/EventService.js:481:12)
    at ClientDuplexStreamImpl.emit (node:events:513:28)
    at addChunk (node:internal/streams/readable:315:12)
    at readableAddChunk (node:internal/streams/readable:289:9)
2024.01.15-17:12:03.456 info  [caliper] [connectors/v2/FabricGateway]   disconnecting gateway for user User1
2024.01.15-17:12:03.458 info  [caliper] [connectors/v2/FabricGateway]   disconnecting gateway for user User1
2024.01.15-17:12:03.459 info  [caliper] [worker-message-handler]    Worker#3 finished Round#1
2024.01.15-17:12:03.459 info  [caliper] [worker-message-handler]    Worker#4 finished Round#1
2024.01.15-17:12:07.346 info  [caliper] [default-observer]  Resetting txCount indicator count
2024.01.15-17:12:12.350 info  [caliper] [default-observer]  [Change car owner. Round 1 Transaction Info] - Submitted: 0 Succ: 0 Fail:0 Unfinished:0
2024.01.15-17:12:17.355 info  [caliper] [default-observer]  [Change car owner. Round 1 Transaction Info] - Submitted: 0 Succ: 0 Fail:0 Unfinished:0
2024.01.15-17:12:22.360 info  [caliper] [default-observer]  [Change car owner. Round 1 Transaction Info] - Submitted: 0 Succ: 0 Fail:0 Unfinished:0
2024.01.15-17:12:27.365 info  [caliper] [default-observer]  [Change car owner. Round 1 Transaction Info] - Submitted: 0 Succ: 0 Fail:0 Unfinished:0
2024.01.15-17:12:32.370 info  [caliper] [default-observer]  [Change car owner. Round 1 Transaction Info] - Submitted: 0 Succ: 0 Fail:0 Unfinished:0
2024.01.15-17:12:37.375 info  [caliper] [default-observer]  [Change car owner. Round 1 Transaction Info] - Submitted: 0 Succ: 0 Fail:0 Unfinished:0
2024.01.15-17:12:42.381 info  [caliper] [default-observer]  [Change car owner. Round 1 Transaction Info] - Submitted: 0 Succ: 0 Fail:0 Unfinished:0
2024.01.15-17:12:47.386 info  [caliper] [default-observer]  [Change car owner. Round 1 Transaction Info] - Submitted: 0 Succ: 0 Fail:0 Unfinished:0
2024.01.15-17:12:52.391 info  [caliper] [default-observer]  [Change car owner. Round 1 Transaction Info] - Submitted: 0 Succ: 0 Fail:0 Unfinished:0
2024.01.15-17:12:57.395 info  [caliper] [default-observer]  [Change car owner. Round 1 Transaction Info] - Submitted: 0 Succ: 0 Fail:0 Unfinished:0
2024.01.15-17:13:02.400 info  [caliper] [default-observer]  [Change car owner. Round 1 Transaction Info] - Submitted: 0 Succ: 0 Fail:0 Unfinished:0
2024.01.15-17:13:07.405 info  [caliper] [default-observer]  [Change car owner. Round 1 Transaction Info] - Submitted: 0 Succ: 0 Fail:0 Unfinished:0
2024.01.15-17:13:12.410 info  [caliper] [default-observer]  [Change car owner. Round 1 Transaction Info] - Submitted: 0 Succ: 0 Fail:0 Unfinished:0
2024.01.15-17:13:17.415 info  [caliper] [default-observer]  [Change car owner. Round 1 Transaction Info] - Submitted: 0 Succ: 0 Fail:0 Unfinished:0
2024.01.15-17:13:22.420 info  [caliper] [default-observer]  [Change car owner. Round 1 Transaction Info] - Submitted: 0 Succ: 0 Fail:0 Unfinished:0
2024.01.15-17:13:27.425 info  [caliper] [default-observer]  [Change car owner. Round 1 Transaction Info] - Submitted: 0 Succ: 0 Fail:0 Unfinished:0
2024.01.15-17:13:32.430 info  [caliper] [default-observer]  [Change car owner. Round 1 Transaction Info] - Submitted: 0 Succ: 0 Fail:0 Unfinished:0
2024.01.15-17:13:37.435 info  [caliper] [default-observer]  [Change car owner. Round 1 Transaction Info] - Submitted: 0 Succ: 0 Fail:0 Unfinished:0
...

### Please provide your benchmark configuration file content, if possible.

```yaml
test:
  workers:
    number: 10
  rounds:
    - label: Create a car.
      txNumber: 200
      rateControl:
        type: fixed-rate
        opts:
          tps: 150
      workload:
        module: benchmarks/samples/fabric/fabcar/createCar.js
    - label: Change car owner.
      txNumber: 1000
      rateControl:
          type: fixed-rate
          opts:
            tps: 150
      workload:
        module: benchmarks/samples/fabric/fabcar/changeCarOwner.js
        arguments:
          assets: 500

### Please provide your network configuration file content, if possible.

```yaml
name: Caliper Benchmarks
version: "2.0.0"

caliper:
  blockchain: fabric

channels:
  # channelName of mychannel matches the name of the channel created by test network
  - channelName: mychannel
    # the chaincodeIDs of all the fabric chaincodes in caliper-benchmarks
    contracts:
    - id: fabcar
    - id: fixed-asset
    - id: marbles
    - id: simple
    - id: smallbank

organizations:
  - mspid: Org1MSP
    # Identities come from cryptogen created material for test-network
    identities:
      certificates:
      - name: 'User1'
        clientPrivateKey:
          path: '../fabric-samples/myNetwork/config/crypto-config/peerOrganizations/org1.example.com/users/User1@org1.example.com/msp/keystore/priv_sk'
        clientSignedCert:
          path: '../fabric-samples/myNetwork/config/crypto-config/peerOrganizations/org1.example.com/users/User1@org1.example.com/msp/signcerts/User1@org1.example.com-cert.pem'
    connectionProfile:
      path: '../fabric-samples/myNetwork/config/crypto-config/peerOrganizations/org1.example.com/connection-org1.yaml'
      discover: true

### Please provide your workload module content, if possible.

```nodejs
'use strict';

const { WorkloadModuleBase } = require('@hyperledger/caliper-core');

const owners = ['Tomoko', 'Brad', 'Jin Soo', 'Max', 'Adrianna', 'Michel', 'Aarav', 'Pari', 'Valeria', 'Shotaro'];

class ChangeCarOwnerWorkload extends WorkloadModuleBase {
    constructor() {
        super();
        this.txIndex = 0;
    }

    async submitTransaction() {
        this.txIndex++;
        let index = Math.floor(Math.random() * 10)
        let carNumber = 'Client' + index + '_CAR';
        // let carNumber = 'Client' + this.workerIndex + '_CAR';
        let newCarOwner = owners[Math.floor(Math.random() * owners.length)];

        let args = {
            contractId: 'fabcar',
            contractVersion: 'v1',
            contractFunction: 'changeCarOwner',
            contractArguments: [carNumber, newCarOwner],
            // timeout: 60
            timeout: 30
        };

        if (this.txIndex === this.roundArguments.assets) {
            this.txIndex = 0;
        }

        await this.sutAdapter.sendRequests(args);
    }
}

function createWorkloadModule() {
    return new ChangeCarOwnerWorkload();
}

module.exports.createWorkloadModule = createWorkloadModule;

Please provide any additional information you deem relevant to the error.

No response

davidkel commented 8 months ago

Looks like some workers are not terminating which is odd. A couple of things to try.

  1. Generate a caliper debug log. Add the following option when you launch the caliper manager and caliper workers (if you are using seperate remote workers) --caliper-logging-targets-file-enabled true this should generate caliper.log files with hopefully more information
  2. Check the resource utilisation on the machine that you are running caliper. You could very well be running out of resource such as CPU/Memory which will have an impact. In order to properly benchmark a fabric network you should not have caliper and fabric on the same machine as they both contend for physical resource which could skew results
javenleee commented 8 months ago

Looks like some workers are not terminating which is odd. A couple of things to try.

  1. Generate a caliper debug log. Add the following option when you launch the caliper manager and caliper workers (if you are using seperate remote workers) --caliper-logging-targets-file-enabled true this should generate caliper.log files with hopefully more information
  2. Check the resource utilisation on the machine that you are running caliper. You could very well be running out of resource such as CPU/Memory which will have an impact. In order to properly benchmark a fabric network you should not have caliper and fabric on the same machine as they both contend for physical resource which could skew results

Thank you for your response. I attempted to review the output logs, which consist of approximately 29,000 lines. While examining the latest portion, I didn't find any evident error logs, only some more detailed information.

[process-messenger]     Process "10862" handling message: {"sender":"10888","recipients":["10862"],"type":"testResult","content":{"subCollectors"      :[],"active":false,"stats":{"metadata":{"workerIndex":4,"roundIndex":1,"roundLabel":"Change car owner.","roundStartTime":1705406186789,"roundFinishTime":1705406195778},"txCounters":{"totalSubmitted      ":100,"totalFinished":100,"totalSuccessful":34,"totalFailed":66},"timestamps":{"firstCreateTime":1705406186792,"lastCreateTime":1705406193670,"firstFinishTime":1705406186913,"lastFinishTime":170540      6195689},"latency":{"successful":{"min":71,"max":2041,"total":14295},"failed":{"min":34,"max":2019,"total":24972}}},"type":"txUpdate"},"date":"2024-01-16T11:56:36.781Z"}

Additionally, I examined the utilization of my system resources. Fortunately, throughout the entire process, the system resource usage did not exceed 30%.

davidkel commented 8 months ago

There may not be any error messages, but maybe the logs can show differences between a worker that completed successfully and one that did not ? The above looks like it indicates worker 4 completed successfully. I must admit I've never really used the tx counter for rounds, I've always used duration and I'm not even sure caliper can guarantee the exact amount of transactions will be sent.

javenleee commented 8 months ago

There may not be any error messages, but maybe the logs can show differences between a worker that completed successfully and one that did not ? The above looks like it indicates worker 4 completed successfully. I must admit I've never really used the tx counter for rounds, I've always used duration and I'm not even sure caliper can guarantee the exact amount of transactions will be sent.

After conducting multiple tests, I indeed discovered that my CPU was being fully utilized. I will attempt to run Caliper and Fabric separately. Once again, thank you for your suggestions.

javenleee commented 8 months ago

This time I set the block size to 1, tps to 5 and only one worker, I'm sure that I didn't run out of cpu this time, but this problem came back, I don't know what's the reason for it

There may not be any error messages, but maybe the logs can show differences between a worker that completed successfully and one that did not ? The above looks like it indicates worker 4 completed successfully. I must admit I've never really used the tx counter for rounds, I've always used duration and I'm not even sure caliper can guarantee the exact amount of transactions will be sent.