From 05403a913c6daf3566ba24d8fc7c6e1fc57cc795 Mon Sep 17 00:00:00 2001 From: pasta Date: Mon, 31 Aug 2026 16:59:28 +0200 Subject: [PATCH 1/4] perf(drive-abci): don't read every withdrawal document to build a debug log line MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit pool_withdrawals_into_transactions_queue_v1 fetches every withdrawal document the chain has ever produced, groups them by status and sorts each group, on any block with nothing queued — nearly every block — and then throws the result away unless debug logging is on. fetch_oldest_withdrawal_documents passes limit: None, and withdrawal documents are never removed, so the cost grows with chain history: measured at 4.8 ms per block by height 200,000 on mainnet and still climbing, against about 7 ms for everything else in a block put together. Do the work only when the line it feeds will be emitted. --- .../v1/mod.rs | 12 +++++++++++- 1 file changed, 11 insertions(+), 1 deletion(-) diff --git a/packages/rs-drive-abci/src/execution/platform_events/withdrawals/pool_withdrawals_into_transactions_queue/v1/mod.rs b/packages/rs-drive-abci/src/execution/platform_events/withdrawals/pool_withdrawals_into_transactions_queue/v1/mod.rs index 8cdb4406ed7..4c58165dfe6 100644 --- a/packages/rs-drive-abci/src/execution/platform_events/withdrawals/pool_withdrawals_into_transactions_queue/v1/mod.rs +++ b/packages/rs-drive-abci/src/execution/platform_events/withdrawals/pool_withdrawals_into_transactions_queue/v1/mod.rs @@ -49,6 +49,16 @@ where .withdrawal_transactions_per_block_limit, "No queued withdrawal documents found to pool into transactions" ); + // Reading every withdrawal document the chain ever produced, only to + // count them for a log line. Withdrawal documents are never removed, + // so this grows without bound with chain history — measured at 4.8 ms + // a block by height 200,000 on mainnet, and it ran on every block + // that had nothing queued, which is nearly all of them. Do it only + // when the line it feeds will actually be emitted. + if !tracing::enabled!(tracing::Level::DEBUG) { + return Ok(()); + } + let all_documents = self .drive .fetch_oldest_withdrawal_documents(transaction, platform_version)?; @@ -57,7 +67,7 @@ where height = block_info.height, "No withdrawal documents found at all" ); - } else if tracing::enabled!(tracing::Level::DEBUG) { + } else { // Count documents by status let queued_count = all_documents .get(&(withdrawals_contract::WithdrawalStatus::QUEUED as u8)) From efd398deebc2fe71c2ad4a040b2de2aaf2eacd78 Mon Sep 17 00:00:00 2001 From: pasta Date: Mon, 7 Sep 2026 16:48:18 -0500 Subject: [PATCH 2/4] fix(drive-abci): keep the withdrawal status summary from failing a block The summary only runs when DEBUG logging is on, so a Drive error inside it would fail the block on a node with verbose logging and pass on one without. Log the error and carry on instead. Two tests with a scoped DEBUG subscriber cover the summary with and without history. --- .../v1/mod.rs | 134 +++++++++++++++++- 1 file changed, 132 insertions(+), 2 deletions(-) diff --git a/packages/rs-drive-abci/src/execution/platform_events/withdrawals/pool_withdrawals_into_transactions_queue/v1/mod.rs b/packages/rs-drive-abci/src/execution/platform_events/withdrawals/pool_withdrawals_into_transactions_queue/v1/mod.rs index 4c58165dfe6..ecef98a9e9e 100644 --- a/packages/rs-drive-abci/src/execution/platform_events/withdrawals/pool_withdrawals_into_transactions_queue/v1/mod.rs +++ b/packages/rs-drive-abci/src/execution/platform_events/withdrawals/pool_withdrawals_into_transactions_queue/v1/mod.rs @@ -59,9 +59,22 @@ where return Ok(()); } - let all_documents = self + // Diagnostic only. Whether this query runs at all depends on the log + // level, so a failure in it must not decide whether the block succeeds. + let all_documents = match self .drive - .fetch_oldest_withdrawal_documents(transaction, platform_version)?; + .fetch_oldest_withdrawal_documents(transaction, platform_version) + { + Ok(all_documents) => all_documents, + Err(error) => { + tracing::debug!( + height = block_info.height, + ?error, + "Unable to fetch withdrawal documents for the status summary" + ); + return Ok(()); + } + }; if all_documents.is_empty() { tracing::debug!( height = block_info.height, @@ -388,4 +401,121 @@ mod tests { assert_eq!(tx_index, i as u64); } } + + /// A DEBUG subscriber, so the status summary behind `tracing::enabled!` runs. + fn init_debug_tracing() -> tracing::subscriber::DefaultGuard { + let subscriber = tracing_subscriber::fmt() + .with_max_level(tracing::Level::DEBUG) + .with_test_writer() + .finish(); + tracing::subscriber::set_default(subscriber) + } + + #[test] + fn test_nothing_queued_with_debug_logging_summarises_without_touching_documents() { + let _guard = init_debug_tracing(); + + let platform_version = PlatformVersion::latest(); + let platform = TestPlatformBuilder::new() + .build_with_mock_rpc() + .set_initial_state_structure(); + + let transaction = platform.drive.grove.start_transaction(); + + let block_info = BlockInfo { + time_ms: 1, + height: 1, + core_height: 96, + epoch: Epoch::default(), + }; + + let data_contract = + load_system_data_contract(SystemDataContract::Withdrawals, platform_version) + .expect("to load system data contract"); + + setup_system_data_contract(&platform.drive, &data_contract, Some(&transaction)); + + // Nothing queued, but history to summarise: one completed withdrawal. + let completed = get_withdrawal_document_fixture( + &data_contract, + Identifier::new([1u8; 32]), + platform_value!({ + "amount": 1000u64, + "coreFeePerByte": 1u32, + "pooling": Pooling::Never as u8, + "outputScript": CoreScript::from_bytes((0..23).collect::>()), + "status": withdrawals_contract::WithdrawalStatus::COMPLETE as u8, + "transactionIndex": 1u64, + }), + None, + platform_version.protocol_version, + ) + .expect("expected withdrawal document"); + + let document_type = data_contract + .document_type_for_name(withdrawal::NAME) + .expect("expected to get document type"); + + setup_document( + &platform.drive, + &completed, + &data_contract, + document_type, + Some(&transaction), + ); + + platform + .pool_withdrawals_into_transactions_queue_v1( + &block_info, + Some(&transaction), + platform_version, + ) + .expect("nothing queued is not an error"); + + let still_complete = platform + .drive + .fetch_oldest_withdrawal_documents_by_status( + withdrawals_contract::WithdrawalStatus::COMPLETE.into(), + DEFAULT_QUERY_LIMIT, + Some(&transaction), + platform_version, + ) + .expect("to fetch withdrawal documents"); + + assert_eq!(still_complete.len(), 1); + assert_eq!(still_complete[0].revision(), completed.revision()); + } + + #[test] + fn test_no_withdrawal_documents_at_all_with_debug_logging() { + let _guard = init_debug_tracing(); + + let platform_version = PlatformVersion::latest(); + let platform = TestPlatformBuilder::new() + .build_with_mock_rpc() + .set_initial_state_structure(); + + let transaction = platform.drive.grove.start_transaction(); + + let block_info = BlockInfo { + time_ms: 1, + height: 1, + core_height: 96, + epoch: Epoch::default(), + }; + + let data_contract = + load_system_data_contract(SystemDataContract::Withdrawals, platform_version) + .expect("to load system data contract"); + + setup_system_data_contract(&platform.drive, &data_contract, Some(&transaction)); + + platform + .pool_withdrawals_into_transactions_queue_v1( + &block_info, + Some(&transaction), + platform_version, + ) + .expect("an empty withdrawal history is not an error"); + } } From cf5e8e4a097e575bc174006f4a5b0d0eb8df972e Mon Sep 17 00:00:00 2001 From: pasta Date: Mon, 7 Sep 2026 19:47:00 -0500 Subject: [PATCH 3/4] test(drive-abci): drop the empty-history withdrawal summary test The one with a document already covers the guarded path; the empty case adds nothing. --- .../v1/mod.rs | 38 ++----------------- 1 file changed, 3 insertions(+), 35 deletions(-) diff --git a/packages/rs-drive-abci/src/execution/platform_events/withdrawals/pool_withdrawals_into_transactions_queue/v1/mod.rs b/packages/rs-drive-abci/src/execution/platform_events/withdrawals/pool_withdrawals_into_transactions_queue/v1/mod.rs index ecef98a9e9e..9f2de592a9a 100644 --- a/packages/rs-drive-abci/src/execution/platform_events/withdrawals/pool_withdrawals_into_transactions_queue/v1/mod.rs +++ b/packages/rs-drive-abci/src/execution/platform_events/withdrawals/pool_withdrawals_into_transactions_queue/v1/mod.rs @@ -402,7 +402,8 @@ mod tests { } } - /// A DEBUG subscriber, so the status summary behind `tracing::enabled!` runs. + /// A DEBUG subscriber, so the status summary behind `tracing::enabled!` runs + /// and the guarded path is exercised. fn init_debug_tracing() -> tracing::subscriber::DefaultGuard { let subscriber = tracing_subscriber::fmt() .with_max_level(tracing::Level::DEBUG) @@ -412,7 +413,7 @@ mod tests { } #[test] - fn test_nothing_queued_with_debug_logging_summarises_without_touching_documents() { + fn test_debug_summary_runs_without_touching_documents() { let _guard = init_debug_tracing(); let platform_version = PlatformVersion::latest(); @@ -485,37 +486,4 @@ mod tests { assert_eq!(still_complete.len(), 1); assert_eq!(still_complete[0].revision(), completed.revision()); } - - #[test] - fn test_no_withdrawal_documents_at_all_with_debug_logging() { - let _guard = init_debug_tracing(); - - let platform_version = PlatformVersion::latest(); - let platform = TestPlatformBuilder::new() - .build_with_mock_rpc() - .set_initial_state_structure(); - - let transaction = platform.drive.grove.start_transaction(); - - let block_info = BlockInfo { - time_ms: 1, - height: 1, - core_height: 96, - epoch: Epoch::default(), - }; - - let data_contract = - load_system_data_contract(SystemDataContract::Withdrawals, platform_version) - .expect("to load system data contract"); - - setup_system_data_contract(&platform.drive, &data_contract, Some(&transaction)); - - platform - .pool_withdrawals_into_transactions_queue_v1( - &block_info, - Some(&transaction), - platform_version, - ) - .expect("an empty withdrawal history is not an error"); - } } From edf1fa41565980c07a040febd0b1b667dfedad2b Mon Sep 17 00:00:00 2001 From: pasta Date: Tue, 8 Sep 2026 14:05:58 -0500 Subject: [PATCH 4/4] perf(drive-abci): remove withdrawal status diagnostic --- .../v1/mod.rs | 155 ------------------ 1 file changed, 155 deletions(-) diff --git a/packages/rs-drive-abci/src/execution/platform_events/withdrawals/pool_withdrawals_into_transactions_queue/v1/mod.rs b/packages/rs-drive-abci/src/execution/platform_events/withdrawals/pool_withdrawals_into_transactions_queue/v1/mod.rs index 9f2de592a9a..d0bb8c3c74a 100644 --- a/packages/rs-drive-abci/src/execution/platform_events/withdrawals/pool_withdrawals_into_transactions_queue/v1/mod.rs +++ b/packages/rs-drive-abci/src/execution/platform_events/withdrawals/pool_withdrawals_into_transactions_queue/v1/mod.rs @@ -49,76 +49,6 @@ where .withdrawal_transactions_per_block_limit, "No queued withdrawal documents found to pool into transactions" ); - // Reading every withdrawal document the chain ever produced, only to - // count them for a log line. Withdrawal documents are never removed, - // so this grows without bound with chain history — measured at 4.8 ms - // a block by height 200,000 on mainnet, and it ran on every block - // that had nothing queued, which is nearly all of them. Do it only - // when the line it feeds will actually be emitted. - if !tracing::enabled!(tracing::Level::DEBUG) { - return Ok(()); - } - - // Diagnostic only. Whether this query runs at all depends on the log - // level, so a failure in it must not decide whether the block succeeds. - let all_documents = match self - .drive - .fetch_oldest_withdrawal_documents(transaction, platform_version) - { - Ok(all_documents) => all_documents, - Err(error) => { - tracing::debug!( - height = block_info.height, - ?error, - "Unable to fetch withdrawal documents for the status summary" - ); - return Ok(()); - } - }; - if all_documents.is_empty() { - tracing::debug!( - height = block_info.height, - "No withdrawal documents found at all" - ); - } else { - // Count documents by status - let queued_count = all_documents - .get(&(withdrawals_contract::WithdrawalStatus::QUEUED as u8)) - .map(|v| v.len()) - .unwrap_or(0); - let pooled_count = all_documents - .get(&(withdrawals_contract::WithdrawalStatus::POOLED as u8)) - .map(|v| v.len()) - .unwrap_or(0); - let broadcasted_count = all_documents - .get(&(withdrawals_contract::WithdrawalStatus::BROADCASTED as u8)) - .map(|v| v.len()) - .unwrap_or(0); - let complete_count = all_documents - .get(&(withdrawals_contract::WithdrawalStatus::COMPLETE as u8)) - .map(|v| v.len()) - .unwrap_or(0); - let expired_count = all_documents - .get(&(withdrawals_contract::WithdrawalStatus::EXPIRED as u8)) - .map(|v| v.len()) - .unwrap_or(0); - let total_documents = queued_count - + pooled_count - + broadcasted_count - + complete_count - + expired_count; - - tracing::debug!( - height = block_info.height, - total_documents, - queued_count, - pooled_count, - broadcasted_count, - complete_count, - expired_count, - "Found withdrawal documents grouped by status" - ); - } return Ok(()); } @@ -401,89 +331,4 @@ mod tests { assert_eq!(tx_index, i as u64); } } - - /// A DEBUG subscriber, so the status summary behind `tracing::enabled!` runs - /// and the guarded path is exercised. - fn init_debug_tracing() -> tracing::subscriber::DefaultGuard { - let subscriber = tracing_subscriber::fmt() - .with_max_level(tracing::Level::DEBUG) - .with_test_writer() - .finish(); - tracing::subscriber::set_default(subscriber) - } - - #[test] - fn test_debug_summary_runs_without_touching_documents() { - let _guard = init_debug_tracing(); - - let platform_version = PlatformVersion::latest(); - let platform = TestPlatformBuilder::new() - .build_with_mock_rpc() - .set_initial_state_structure(); - - let transaction = platform.drive.grove.start_transaction(); - - let block_info = BlockInfo { - time_ms: 1, - height: 1, - core_height: 96, - epoch: Epoch::default(), - }; - - let data_contract = - load_system_data_contract(SystemDataContract::Withdrawals, platform_version) - .expect("to load system data contract"); - - setup_system_data_contract(&platform.drive, &data_contract, Some(&transaction)); - - // Nothing queued, but history to summarise: one completed withdrawal. - let completed = get_withdrawal_document_fixture( - &data_contract, - Identifier::new([1u8; 32]), - platform_value!({ - "amount": 1000u64, - "coreFeePerByte": 1u32, - "pooling": Pooling::Never as u8, - "outputScript": CoreScript::from_bytes((0..23).collect::>()), - "status": withdrawals_contract::WithdrawalStatus::COMPLETE as u8, - "transactionIndex": 1u64, - }), - None, - platform_version.protocol_version, - ) - .expect("expected withdrawal document"); - - let document_type = data_contract - .document_type_for_name(withdrawal::NAME) - .expect("expected to get document type"); - - setup_document( - &platform.drive, - &completed, - &data_contract, - document_type, - Some(&transaction), - ); - - platform - .pool_withdrawals_into_transactions_queue_v1( - &block_info, - Some(&transaction), - platform_version, - ) - .expect("nothing queued is not an error"); - - let still_complete = platform - .drive - .fetch_oldest_withdrawal_documents_by_status( - withdrawals_contract::WithdrawalStatus::COMPLETE.into(), - DEFAULT_QUERY_LIMIT, - Some(&transaction), - platform_version, - ) - .expect("to fetch withdrawal documents"); - - assert_eq!(still_complete.len(), 1); - assert_eq!(still_complete[0].revision(), completed.revision()); - } }