Base node/Mempool very sluggish to respond to `NewBlockTemplateRequest` with large mempool
Closed this issue · 2 comments
hansieodendaal commented
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
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
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
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?;
}
hansieodendaal commented
See #6220