Substrate: Low TPS

[maxsam4]

After #2308 was solved, I decided to test the actual TPS by sending tx form multiple accounts. To my surprise, I was only able to do around 25-30 TPS.

I did the tests on a node running locally on dev chain.

I created the following script for the test

const { ApiPromise, WsProvider } = require('@polkadot/api');
const { Keyring } = require('@polkadot/keyring');
const BN = require('bn.js');

const BOB = '5FHneW46xGXgs5mUiveU4sbTyGBzmstUspZC92UhjJM694ty';

async function main () {
  const provider = new WsProvider('ws://127.0.0.1:9944');
  const api = await ApiPromise.create(provider);
  const keyring = new Keyring();
  let accounts = [];
  accounts.push(keyring.addFromMnemonic('enhance embody priority wise tree pig trash reform drum sure zebra canoe', {"name": "test5"}, "sr25519"));
  accounts.push(keyring.addFromMnemonic('game scissors wet budget cradle coil iron quantum chapter dismiss spring catch', {"name": "test6"}, "sr25519"));
  accounts.push(keyring.addFromMnemonic('property rocket unlock wrap shoot useful drip brown genius kingdom keen scan', {"name": "test7"}, "sr25519"));
  accounts.push(keyring.addFromMnemonic('catalog double brother describe orchard kidney want pupil place debris either coral', {"name": "test8"}, "sr25519"));
  console.time('Transactions sent to the node in');
  for (let i = 0; i < accounts.length; i++) {
    let rawNonce = await api.query.system.accountNonce(keyring.getPairs()[i].address());
    let nonce = new BN(rawNonce.toString());
    for (let j = 0; j < 250; j++) {
      const transfer = api.tx.balances.transfer(BOB, 1000);
      transfer.signAndSend(accounts[i], { nonce });
      nonce = nonce.add(new BN(1));
    }
  }
  const unsub = await api.rpc.chain.subscribeNewHead((header) => {
    console.log("Block " + header.blockNumber + " Mined.");
  });
  console.timeEnd('Transactions sent to the node in');
  let i = 0;
  let j = 0;
  let oldPendingTx = 0;
  let interval = setInterval(async () => {
    await api.rpc.author.pendingExtrinsics((extrinsics) => {
      i++;
      j++;
      if (oldPendingTx > extrinsics.length) {
        console.log("Approx TPS: ", (oldPendingTx - extrinsics.length)/j);
        j = 0;
      }
      if(extrinsics.length === 0){
        console.log(i + " Second passed, No pending extrinsics in the pool.");
        clearInterval(interval);
        unsub();
        process.exit();
      }
      console.log(i + " Second passed, " + extrinsics.length + " pending extrinsics in the pool");
      oldPendingTx = extrinsics.length;
    });
  }, 1000);
}

main().catch(console.error);

Sample output is

$ node loadTest.js 
Block 643 Mined.
Transactions sent to the node in: 2220.435ms
1 Second passed, 1000 pending extrinsics in the pool
2 Second passed, 1000 pending extrinsics in the pool
3 Second passed, 1000 pending extrinsics in the pool
4 Second passed, 1000 pending extrinsics in the pool
5 Second passed, 1000 pending extrinsics in the pool
6 Second passed, 1000 pending extrinsics in the pool
7 Second passed, 1000 pending extrinsics in the pool
8 Second passed, 1000 pending extrinsics in the pool
9 Second passed, 1000 pending extrinsics in the pool
10 Second passed, 1000 pending extrinsics in the pool
11 Second passed, 1000 pending extrinsics in the pool
12 Second passed, 1000 pending extrinsics in the pool
Block 644 Mined.
Approx TPS:  20.384615384615383
13 Second passed, 735 pending extrinsics in the pool
14 Second passed, 735 pending extrinsics in the pool
15 Second passed, 735 pending extrinsics in the pool
16 Second passed, 735 pending extrinsics in the pool
17 Second passed, 735 pending extrinsics in the pool
18 Second passed, 735 pending extrinsics in the pool
19 Second passed, 735 pending extrinsics in the pool
20 Second passed, 735 pending extrinsics in the pool
21 Second passed, 735 pending extrinsics in the pool
22 Second passed, 735 pending extrinsics in the pool
Block 645 Mined.
Approx TPS:  26.4
23 Second passed, 471 pending extrinsics in the pool
24 Second passed, 471 pending extrinsics in the pool
25 Second passed, 471 pending extrinsics in the pool
26 Second passed, 471 pending extrinsics in the pool
27 Second passed, 471 pending extrinsics in the pool
28 Second passed, 471 pending extrinsics in the pool
29 Second passed, 471 pending extrinsics in the pool
30 Second passed, 471 pending extrinsics in the pool
31 Second passed, 471 pending extrinsics in the pool
32 Second passed, 471 pending extrinsics in the pool
Block 646 Mined.
Approx TPS:  26.3
33 Second passed, 208 pending extrinsics in the pool
34 Second passed, 208 pending extrinsics in the pool
35 Second passed, 208 pending extrinsics in the pool
36 Second passed, 208 pending extrinsics in the pool
37 Second passed, 208 pending extrinsics in the pool
38 Second passed, 208 pending extrinsics in the pool
39 Second passed, 208 pending extrinsics in the pool
Block 647 Mined.
Approx TPS:  29.714285714285715
40 Second passed, No pending extrinsics in the pool.

During the process, substrate used 100% of one of my core but only one of my core. Is such a low TPS expected? Can you anyone else please run the script on their system and verify the TPS they are managing?

To run the script
1) Create a new npm project do npm install @polkadot/api bn.js.
2) Run the substrate node with --pool-limit 1000000 flag.
3) Add these 4 Schnorrkel mnemonic accounts and send a lot of funds to them. Use sudo to set their balance to a few yetta or whatever that largest unit is.

enhance embody priority wise tree pig trash reform drum sure zebra canoe
game scissors wet budget cradle coil iron quantum chapter dismiss spring catch
property rocket unlock wrap shoot useful drip brown genius kingdom keen scan
catalog double brother describe orchard kidney want pupil place debris either coral

3) Run the script via node loadTest.js

[maxsam4]

More info
1) Blocks are probably not full. 4MB block should be able to fit 20k+ such transactions according to my estimate.
2) I am using an i7 - 8750H processor.
3) These are limits when there is no network involved. I am sure the limit will go down if we start using a network.
4) A private network on Parity eth client can do 2000+ TPS so 25 TPS for substrate is very low.

[rphmeier]

The authoring pipeline is not particularly optimized at the moment and needs to be looked at.

[vjoke]

I got 5.2 TPS for a single substrate node for debug version.

[gavofyork]

Issues should cover a single bug or feature: "it should be faster" is too vague and nebulous to be in the issue tracker.

[maxsam4]

As @rphmeier mentioned, the actual issue is the unoptimized authoring pipeline. Bug 1 of Ubuntu was "Microsoft has a majority market share". I am no expert but "Component X is unoptimized" seems not too vague in comparison. Anyway, I understand why you might not want to keep this open.

@gavofyork Can you please at least comment on if this is something that will be looked into in nearby future?

Thanks for all your work on Substrate regardless. Really appreciate it. I'd praise substrate more but I don't want to get kicked out of the ethereum community just yet :P.

I'll try to iron this bug out in future once I understand the substrate architecture and rust well enough.

tbh, this is more of a Feature Request than a bug. Not sure if there is a separate place to track those for substrate.

[maxsam4]

Substrate was touted to have ~1k tx/s pre polkadot btw
http://slides.com/paritytech/paritysubstrate#/30