Base node/Mempool very sluggish to respond to `NewBlockTemplateRequest` with large mempool

Question

Base node/Mempool very sluggish to respond to `NewBlockTemplateRequest` with large mempool

Closed this issue 5 months ago · 2 comments

See the increasing response times of a monitored base node responding to a SHA3 miner from 23:31:32 onwards during a coin-split stress test (esmeralda ):

2024-03-14 23:20:17.887142000 [minotari::base_node::grpc] TRACE Request NewBlockTemplateRequest { algo: Some(PowAlgo { pow_algo: Sha3x }), max_weight: 0 }
2024-03-14 23:20:18.494154300 [minotari::base_node::grpc] DEBUG Sending GetNewBlockTemplate response to client

2024-03-14 23:21:22.430445800 [minotari::base_node::grpc] TRACE Request NewBlockTemplateRequest { algo: Some(PowAlgo { pow_algo: Sha3x }), max_weight: 0 }
2024-03-14 23:21:22.447345300 [minotari::base_node::grpc] DEBUG Sending GetNewBlockTemplate response to client

2024-03-14 23:21:25.207184200 [minotari::base_node::grpc] TRACE Request NewBlockTemplateRequest { algo: Some(PowAlgo { pow_algo: Sha3x }), max_weight: 0 }
2024-03-14 23:21:25.605665700 [minotari::base_node::grpc] DEBUG Sending GetNewBlockTemplate response to client

2024-03-14 23:22:17.629494500 [minotari::base_node::grpc] TRACE Request NewBlockTemplateRequest { algo: Some(PowAlgo { pow_algo: Sha3x }), max_weight: 0 }
2024-03-14 23:22:18.031947400 [minotari::base_node::grpc] DEBUG Sending GetNewBlockTemplate response to client

2024-03-14 23:28:43.154192900 [minotari::base_node::grpc] TRACE Request NewBlockTemplateRequest { algo: Some(PowAlgo { pow_algo: Sha3x }), max_weight: 0 }
2024-03-14 23:28:43.548047700 [minotari::base_node::grpc] DEBUG Sending GetNewBlockTemplate response to client

2024-03-14 23:30:39.172218100 [minotari::base_node::grpc] TRACE Request NewBlockTemplateRequest { algo: Some(PowAlgo { pow_algo: Sha3x }), max_weight: 0 }
2024-03-14 23:30:39.192033700 [minotari::base_node::grpc] DEBUG Sending GetNewBlockTemplate response to client

2024-03-14 23:31:32.627521500 [minotari::base_node::grpc] TRACE Request NewBlockTemplateRequest { algo: Some(PowAlgo { pow_algo: Sha3x }), max_weight: 0 }
2024-03-14 23:37:17.500319200 [minotari::base_node::grpc] DEBUG Sending GetNewBlockTemplate response to client

2024-03-14 23:37:17.540602200 [minotari::base_node::grpc] TRACE Request NewBlockTemplateRequest { algo: Some(PowAlgo { pow_algo: Sha3x }), max_weight: 0 }
2024-03-14 23:42:56.050588800 [minotari::base_node::grpc] DEBUG Sending GetNewBlockTemplate response to client

2024-03-14 23:42:56.086647700 [minotari::base_node::grpc] TRACE Request NewBlockTemplateRequest { algo: Some(PowAlgo { pow_algo: Sha3x }), max_weight: 0 }
2024-03-14 23:54:05.121736600 [minotari::base_node::grpc] DEBUG Sending GetNewBlockTemplate response to client

2024-03-14 23:54:05.144896700 [minotari::base_node::grpc] TRACE Request NewBlockTemplateRequest { algo: Some(PowAlgo { pow_algo: Sha3x }), max_weight: 0 }
2024-03-15 00:32:04.015638500 [minotari::base_node::grpc] DEBUG Sending GetNewBlockTemplate response to client

2024-03-15 00:32:04.044773500 [minotari::base_node::grpc] TRACE Request NewBlockTemplateRequest { algo: Some(PowAlgo { pow_algo: Sha3x }), max_weight: 0 }
2024-03-15 01:03:33.720355900 [minotari::base_node::grpc] DEBUG Sending GetNewBlockTemplate response to client

2024-03-15 01:03:33.740228200 [minotari::base_node::grpc] TRACE Request NewBlockTemplateRequest { algo: Some(PowAlgo { pow_algo: Sha3x }), max_weight: 0 }
2024-03-15 01:38:42.260214200 [minotari::base_node::grpc] DEBUG Sending GetNewBlockTemplate response to client

2024-03-15 01:38:42.280939800 [minotari::base_node::grpc] TRACE Request NewBlockTemplateRequest { algo: Some(PowAlgo { pow_algo: Sha3x }), max_weight: 0 }
2024-03-15 02:40:53.461162800 [minotari::base_node::grpc] DEBUG Sending GetNewBlockTemplate response to client

2024-03-15 02:40:53.479553100 [minotari::base_node::grpc] TRACE Request NewBlockTemplateRequest { algo: Some(PowAlgo { pow_algo: Sha3x }), max_weight: 0 }
2024-03-15 04:04:35.913416500 [minotari::base_node::grpc] DEBUG Sending GetNewBlockTemplate response to client

Log file for logs between these events:

2024-03-14 23:37:17.540602200 [minotari::base_node::grpc] TRACE Request NewBlockTemplateRequest { algo: Some(PowAlgo { pow_a
2024-03-14 23:42:56.050588800 [minotari::base_node::grpc] DEBUG Sending GetNewBlockTemplate response to client

core.8a.log.zip

Log file for logs between these events:

2024-03-14 23:42:56.086647700 [minotari::base_node::grpc] TRACE Request NewBlockTemplateRequest { algo: Some(PowAlgo { pow_algo: Sha3x }), max_weight: 0 }
2024-03-14 23:54:05.121736600 [minotari::base_node::grpc] DEBUG Sending GetNewBlockTemplate response to client

core.8b.log.zip

Base node console with mempool stats

23:28 v1.0.0-pre.11a esmeralda State: Listening Tip: 1434 (Thu, 14 Mar 2024 21:22:12 +0000) Mempool: 1246tx (35533428g, +/- 279blks) Connections: 13|10 Banned: 0 Messages (last 60s): 31 Rpc: 172/10000
23:28 v1.0.0-pre.11a esmeralda State: Listening Tip: 1434 (Thu, 14 Mar 2024 21:22:12 +0000) Mempool: 1246tx (35533428g, +/- 279blks) Connections: 12|10 Banned: 0 Messages (last 60s): 28 Rpc: 172/10000
23:28 v1.0.0-pre.11a esmeralda State: Listening Tip: 1434 (Thu, 14 Mar 2024 21:22:12 +0000) Mempool: 1246tx (35533428g, +/- 279blks) Connections: 12|10 Banned: 0 Messages (last 60s): 28 Rpc: 172/10000
23:28 v1.0.0-pre.11a esmeralda State: Listening Tip: 1434 (Thu, 14 Mar 2024 21:22:12 +0000) Mempool: 1246tx (35533428g, +/- 279blks) Connections: 12|10 Banned: 0 Messages (last 60s): 34 Rpc: 172/10000
23:28 v1.0.0-pre.11a esmeralda State: Listening Tip: 1434 (Thu, 14 Mar 2024 21:22:12 +0000) Mempool: 1246tx (35533428g, +/- 279blks) Connections: 12|10 Banned: 0 Messages (last 60s): 34 Rpc: 172/10000
23:28 v1.0.0-pre.11a esmeralda State: Listening Tip: 1435 (Thu, 14 Mar 2024 21:28:37 +0000) Mempool: 1242tx (35419356g, +/- 278blks) Connections: 12|10 Banned: 0 Messages (last 60s): 39 Rpc: 172/10000
23:28 v1.0.0-pre.11a esmeralda State: Listening Tip: 1435 (Thu, 14 Mar 2024 21:28:37 +0000) Mempool: 1242tx (35419356g, +/- 278blks) Connections: 12|10 Banned: 0 Messages (last 60s): 40 Rpc: 172/10000
23:28 v1.0.0-pre.11a esmeralda State: Listening Tip: 1435 (Thu, 14 Mar 2024 21:28:37 +0000) Mempool: 1242tx (35419356g, +/- 278blks) Connections: 12|10 Banned: 0 Messages (last 60s): 40 Rpc: 172/10000
23:29 v1.0.0-pre.11a esmeralda State: Listening Tip: 1435 (Thu, 14 Mar 2024 21:28:37 +0000) Mempool: 1242tx (35419356g, +/- 278blks) Connections: 12|10 Banned: 0 Messages (last 60s): 41 Rpc: 172/10000
23:29 v1.0.0-pre.11a esmeralda State: Listening Tip: 1435 (Thu, 14 Mar 2024 21:28:37 +0000) Mempool: 1242tx (35419356g, +/- 278blks) Connections: 12|10 Banned: 0 Messages (last 60s): 39 Rpc: 172/10000 RandomX: #1 with flags FLAG_HARD_AES | FLAG_JIT | FLAG_ARGON2_SSSE3 | FLAG_ARGON2_AVX2 | FLAG_ARGON2
23:29 v1.0.0-pre.11a esmeralda State: Listening Tip: 1435 (Thu, 14 Mar 2024 21:28:37 +0000) Mempool: 1242tx (35419356g, +/- 278blks) Connections: 12|10 Banned: 0 Messages (last 60s): 40 Rpc: 172/10000
23:29 v1.0.0-pre.11a esmeralda State: Listening Tip: 1435 (Thu, 14 Mar 2024 21:28:37 +0000) Mempool: 1242tx (35419356g, +/- 278blks) Connections: 13|10 Banned: 0 Messages (last 60s): 39 Rpc: 172/10000
23:29 v1.0.0-pre.11a esmeralda State: Listening Tip: 1435 (Thu, 14 Mar 2024 21:28:37 +0000) Mempool: 1242tx (35419356g, +/- 278blks) Connections: 13|10 Banned: 0 Messages (last 60s): 41 Rpc: 172/10000
23:29 v1.0.0-pre.11a esmeralda State: Listening Tip: 1435 (Thu, 14 Mar 2024 21:28:37 +0000) Mempool: 1242tx (35419356g, +/- 278blks) Connections: 13|10 Banned: 0 Messages (last 60s): 41 Rpc: 172/10000
23:29 v1.0.0-pre.11a esmeralda State: Listening Tip: 1435 (Thu, 14 Mar 2024 21:28:37 +0000) Mempool: 1242tx (35419356g, +/- 278blks) Connections: 13|10 Banned: 0 Messages (last 60s): 37 Rpc: 172/10000
23:29 v1.0.0-pre.11a esmeralda State: Listening Tip: 1435 (Thu, 14 Mar 2024 21:28:37 +0000) Mempool: 1242tx (35419356g, +/- 278blks) Connections: 13|10 Banned: 0 Messages (last 60s): 38 Rpc: 172/10000
23:29 v1.0.0-pre.11a esmeralda State: Listening Tip: 1435 (Thu, 14 Mar 2024 21:28:37 +0000) Mempool: 1242tx (35419356g, +/- 278blks) Connections: 13|10 Banned: 0 Messages (last 60s): 33 Rpc: 172/10000
23:29 v1.0.0-pre.11a esmeralda State: Listening Tip: 1435 (Thu, 14 Mar 2024 21:28:37 +0000) Mempool: 1242tx (35419356g, +/- 278blks) Connections: 13|10 Banned: 0 Messages (last 60s): 34 Rpc: 172/10000
23:29 v1.0.0-pre.11a esmeralda State: Listening Tip: 1435 (Thu, 14 Mar 2024 21:28:37 +0000) Mempool: 1242tx (35419356g, +/- 278blks) Connections: 13|10 Banned: 0 Messages (last 60s): 31 Rpc: 172/10000
23:29 v1.0.0-pre.11a esmeralda State: Listening Tip: 1435 (Thu, 14 Mar 2024 21:28:37 +0000) Mempool: 1242tx (35419356g, +/- 278blks) Connections: 13|10 Banned: 0 Messages (last 60s): 30 Rpc: 172/10000
23:30 v1.0.0-pre.11a esmeralda State: Listening Tip: 1435 (Thu, 14 Mar 2024 21:28:37 +0000) Mempool: 1242tx (35419356g, +/- 278blks) Connections: 13|10 Banned: 0 Messages (last 60s): 31 Rpc: 172/10000
23:30 v1.0.0-pre.11a esmeralda State: Listening Tip: 1435 (Thu, 14 Mar 2024 21:28:37 +0000) Mempool: 1242tx (35419356g, +/- 278blks) Connections: 13|10 Banned: 0 Messages (last 60s): 32 Rpc: 172/10000
23:30 v1.0.0-pre.11a esmeralda State: Listening Tip: 1435 (Thu, 14 Mar 2024 21:28:37 +0000) Mempool: 1242tx (35419356g, +/- 278blks) Connections: 13|10 Banned: 0 Messages (last 60s): 32 Rpc: 172/10000
23:30 v1.0.0-pre.11a esmeralda State: Listening Tip: 1435 (Thu, 14 Mar 2024 21:28:37 +0000) Mempool: 1242tx (35419356g, +/- 278blks) Connections: 13|10 Banned: 0 Messages (last 60s): 31 Rpc: 172/10000
23:30 v1.0.0-pre.11a esmeralda State: Listening Tip: 1435 (Thu, 14 Mar 2024 21:28:37 +0000) Mempool: 1242tx (35419356g, +/- 278blks) Connections: 13|10 Banned: 0 Messages (last 60s): 34 Rpc: 172/10000
23:30 v1.0.0-pre.11a esmeralda State: Listening Tip: 1435 (Thu, 14 Mar 2024 21:28:37 +0000) Mempool: 1242tx (35419356g, +/- 278blks) Connections: 13|10 Banned: 0 Messages (last 60s): 34 Rpc: 172/10000
23:30 v1.0.0-pre.11a esmeralda State: Listening Tip: 1436 (Thu, 14 Mar 2024 21:28:46 +0000) Mempool: 1238tx (35305284g, +/- 277blks) Connections: 13|10 Banned: 0 Messages (last 60s): 44 Rpc: 173/10000
23:30 v1.0.0-pre.11a esmeralda State: Listening Tip: 1436 (Thu, 14 Mar 2024 21:28:46 +0000) Mempool: 1238tx (35305284g, +/- 277blks) Connections: 13|10 Banned: 0 Messages (last 60s): 43 Rpc: 173/10000
23:30 v1.0.0-pre.11a esmeralda State: Listening Tip: 1436 (Thu, 14 Mar 2024 21:28:46 +0000) Mempool: 1238tx (35305284g, +/- 277blks) Connections: 13|10 Banned: 0 Messages (last 60s): 45 Rpc: 173/10000
23:30 v1.0.0-pre.11a esmeralda State: Listening Tip: 1436 (Thu, 14 Mar 2024 21:28:46 +0000) Mempool: 1238tx (35305284g, +/- 277blks) Connections: 13|10 Banned: 0 Messages (last 60s): 48 Rpc: 173/10000
23:30 v1.0.0-pre.11a esmeralda State: Listening Tip: 1436 (Thu, 14 Mar 2024 21:28:46 +0000) Mempool: 1238tx (35305284g, +/- 277blks) Connections: 13|10 Banned: 0 Messages (last 60s): 49 Rpc: 173/10000
23:31 v1.0.0-pre.11a esmeralda State: Listening Tip: 1436 (Thu, 14 Mar 2024 21:28:46 +0000) Mempool: 1238tx (35305284g, +/- 277blks) Connections: 13|10 Banned: 0 Messages (last 60s): 52 Rpc: 172/10000
23:31 v1.0.0-pre.11a esmeralda State: Listening Tip: 1436 (Thu, 14 Mar 2024 21:28:46 +0000) Mempool: 1238tx (35305284g, +/- 277blks) Connections: 13|10 Banned: 0 Messages (last 60s): 53 Rpc: 172/10000 RandomX: #1 with flags FLAG_HARD_AES | FLAG_JIT | FLAG_ARGON2_SSSE3 | FLAG_ARGON2_AVX2 | FLAG_ARGON2
23:31 v1.0.0-pre.11a esmeralda State: Listening Tip: 1436 (Thu, 14 Mar 2024 21:28:46 +0000) Mempool: 1238tx (35305284g, +/- 277blks) Connections: 13|10 Banned: 0 Messages (last 60s): 53 Rpc: 172/10000
23:31 v1.0.0-pre.11a esmeralda State: Listening Tip: 1436 (Thu, 14 Mar 2024 21:28:46 +0000) Mempool: 1238tx (35305284g, +/- 277blks) Connections: 13|10 Banned: 0 Messages (last 60s): 51 Rpc: 172/10000
23:31 v1.0.0-pre.11a esmeralda State: Listening Tip: 1436 (Thu, 14 Mar 2024 21:28:46 +0000) Mempool: 1238tx (35305284g, +/- 277blks) Connections: 13|10 Banned: 0 Messages (last 60s): 49 Rpc: 172/10000
23:31 v1.0.0-pre.11a esmeralda State: Listening Tip: 1437 (Thu, 14 Mar 2024 21:30:31 +0000) Mempool: 1234tx (35191212g, +/- 276blks) Connections: 13|10 Banned: 0 Messages (last 60s): 58 Rpc: 172/10000

hansieodendaal commented 5 months ago

See #6220

Answer 1 · 2024-03-15T06:48:43.000Z

Miner view - Getting new block template is just before the request is sent and Checking if base node is synced just after the response is received:

2024-03-14 23:20:17.838603000 [minotari::miner::main] DEBUG Getting new block template
2024-03-14 23:20:18.514722500 [minotari::miner::main] DEBUG Checking if base node is synced, because mine_on_tip_only is true

2024-03-14 23:21:22.430112000 [minotari::miner::main] DEBUG Getting new block template
2024-03-14 23:21:22.461671800 [minotari::miner::main] DEBUG Checking if base node is synced, because mine_on_tip_only is true

2024-03-14 23:21:25.159752600 [minotari::miner::main] DEBUG Getting new block template
2024-03-14 23:21:25.621234400 [minotari::miner::main] DEBUG Checking if base node is synced, because mine_on_tip_only is true

2024-03-14 23:22:17.580094600 [minotari::miner::main] DEBUG Getting new block template
2024-03-14 23:22:18.044954900 [minotari::miner::main] DEBUG Checking if base node is synced, because mine_on_tip_only is true

2024-03-14 23:28:43.105425300 [minotari::miner::main] DEBUG Getting new block template
2024-03-14 23:28:43.562282300 [minotari::miner::main] DEBUG Checking if base node is synced, because mine_on_tip_only is true

2024-03-14 23:30:39.171797800 [minotari::miner::main] DEBUG Getting new block template
2024-03-14 23:30:39.208044900 [minotari::miner::main] DEBUG Checking if base node is synced, because mine_on_tip_only is true

2024-03-14 23:31:32.627137300 [minotari::miner::main] DEBUG Getting new block template
2024-03-14 23:37:17.534184900 [minotari::miner::main] DEBUG Checking if base node is synced, because mine_on_tip_only is true

2024-03-14 23:37:17.540080300 [minotari::miner::main] DEBUG Getting new block template
2024-03-14 23:42:56.082318100 [minotari::miner::main] DEBUG Checking if base node is synced, because mine_on_tip_only is true

2024-03-14 23:42:56.086257300 [minotari::miner::main] DEBUG Getting new block template
2024-03-14 23:54:05.139609100 [minotari::miner::main] DEBUG Checking if base node is synced, because mine_on_tip_only is true

2024-03-14 23:54:05.144405600 [minotari::miner::main] DEBUG Getting new block template
2024-03-15 00:32:04.038890600 [minotari::miner::main] DEBUG Checking if base node is synced, because mine_on_tip_only is true

2024-03-15 00:32:04.044246800 [minotari::miner::main] DEBUG Getting new block template
2024-03-15 01:03:33.735850600 [minotari::miner::main] DEBUG Checking if base node is synced, because mine_on_tip_only is true

2024-03-15 01:03:33.739846900 [minotari::miner::main] DEBUG Getting new block template
2024-03-15 01:38:42.276708900 [minotari::miner::main] DEBUG Checking if base node is synced, because mine_on_tip_only is true

2024-03-15 01:38:42.280495900 [minotari::miner::main] DEBUG Getting new block template
2024-03-15 02:40:53.475836900 [minotari::miner::main] DEBUG Checking if base node is synced, because mine_on_tip_only is true

2024-03-15 02:40:53.479159400 [minotari::miner::main] DEBUG Getting new block template
2024-03-15 04:04:35.950210300 [minotari::miner::main] DEBUG Checking if base node is synced, because mine_on_tip_only is true

The miner code snippet:

async fn mining_cycle(
    node_conn: &mut BaseNodeGrpcClient,
    config: &MinerConfig,
    cli: &Cli,
    key_manager: &MemoryDbKeyManager,
    wallet_payment_address: &TariAddress,
    consensus_manager: &ConsensusManager,
) -> Result<bool, MinerError> {
    debug!(target: LOG_TARGET, "Getting new block template");
    let template_response = node_conn
        .get_new_block_template(config.pow_algo_request())
        .await?
        .into_inner();
    let mut block_template = template_response
        .new_block_template
        .clone()
        .ok_or_else(|| err_empty("new_block_template"))?;
    let height = block_template
        .header
        .as_ref()
        .ok_or_else(|| err_empty("header"))?
        .height;

    if config.mine_on_tip_only {
        debug!(
            target: LOG_TARGET,
            "Checking if base node is synced, because mine_on_tip_only is true"
        );
        validate_tip(node_conn, height, cli.mine_until_height).await?;
    }