diff --git a/crates/common/src/raindex_client/order_quotes.rs b/crates/common/src/raindex_client/order_quotes.rs index ecf7ae6476..c77821c67c 100644 --- a/crates/common/src/raindex_client/order_quotes.rs +++ b/crates/common/src/raindex_client/order_quotes.rs @@ -1,6 +1,7 @@ use super::*; use crate::raindex_client::orders::RaindexOrder; use crate::raindex_client::orders_list::RaindexOrders; +use crate::utils::timing::Timing; use alloy::primitives::Address; use rain_math_float::Float; use rain_orderbook_bindings::IRaindexV6::{OrderV4, SignedContextV1}; @@ -10,6 +11,7 @@ use rain_orderbook_quote::{ }; use rain_orderbook_subgraph_client::utils::float::{F0, F1}; use std::ops::{Div, Mul}; +use tracing::{debug, info, warn}; use wasm_bindgen_utils::impl_wasm_traits; #[derive(Serialize, Deserialize, Debug, Clone, Tsify)] @@ -269,13 +271,23 @@ pub async fn get_order_quotes_batch_with_injector( counterparty: Address, injector: &dyn SignedContextInjector, ) -> Result>, RaindexError> { + let started_at = Timing::now(); if orders.is_empty() { + info!( + order_count = 0usize, + "quote batch skipped for empty order list" + ); return Ok(vec![]); } let expected_chain_id = orders[0].chain_id(); for order in &orders[1..] { if order.chain_id() != expected_chain_id { + warn!( + expected_chain_id, + found_chain_id = order.chain_id(), + "quote batch rejected mixed chain IDs" + ); return Err(RaindexError::PreflightError(format!( "All orders must share the same chain ID, expected {} but found {}", expected_chain_id, @@ -289,6 +301,7 @@ pub async fn get_order_quotes_batch_with_injector( .into_iter() .map(|u| u.to_string()) .collect(); + let rpc_url_count = rpcs.len(); let sg_orders = orders .iter() @@ -310,6 +323,17 @@ pub async fn get_order_quotes_batch_with_injector( Ok::(count) }) .collect::, _>>()?; + let total_pair_count: usize = pair_counts.iter().sum(); + + info!( + order_count = orders.len(), + expected_chain_id, + total_pair_count, + chunk_size = ?chunk_size, + block_number = ?block_number, + rpc_url_count, + "starting order quote batch" + ); let flat_results = get_order_quotes( sg_orders, @@ -325,6 +349,16 @@ pub async fn get_order_quotes_batch_with_injector( .into_iter() .map(RaindexOrderQuote::try_from_batch_order_quotes_response) .collect::, _>>()?; + let successful_quote_count = flat_raindex.iter().filter(|quote| quote.success).count(); + let failed_quote_count = flat_raindex.len().saturating_sub(successful_quote_count); + for quote in flat_raindex.iter().filter(|quote| !quote.success) { + debug!( + input_index = quote.pair.input_index, + output_index = quote.pair.output_index, + error = ?quote.error, + "order quote failed" + ); + } let mut result = Vec::with_capacity(orders.len()); let mut offset = 0; @@ -332,6 +366,31 @@ pub async fn get_order_quotes_batch_with_injector( result.push(flat_raindex[offset..offset + count].to_vec()); offset += count; } + for (order, quotes) in orders.iter().zip(&result) { + for quote in quotes.iter().filter(|quote| !quote.success) { + debug!( + order_hash = %order.order_hash(), + orderbook = %order.orderbook(), + input_index = quote.pair.input_index, + output_index = quote.pair.output_index, + error = ?quote.error, + "order quote failed for order" + ); + } + } + + info!( + order_count = orders.len(), + expected_chain_id, + total_pair_count, + chunk_size = ?chunk_size, + block_number = ?block_number, + rpc_url_count, + successful_quote_count, + failed_quote_count, + duration_ms = started_at.elapsed_ms(), + "completed order quote batch" + ); Ok(result) } diff --git a/crates/common/src/raindex_client/orders.rs b/crates/common/src/raindex_client/orders.rs index 7330086285..3d811326b0 100644 --- a/crates/common/src/raindex_client/orders.rs +++ b/crates/common/src/raindex_client/orders.rs @@ -17,6 +17,7 @@ use crate::raindex_client::take_orders::{ use crate::raindex_client::vaults_list::RaindexVaultsList; use crate::rpc_client::RpcClient; use crate::take_orders::{ParsedTakeOrdersMode, TakeOrdersMode}; +use crate::utils::timing::Timing; use crate::{ meta::TryDecodeRainlangSource, raindex_client::{ @@ -46,6 +47,7 @@ use rain_orderbook_subgraph_client::{ }; use serde::{Deserialize, Serialize}; use std::{collections::HashSet, io::Cursor, str::FromStr}; +use tracing::{info, warn}; use tsify::Tsify; use wasm_bindgen_utils::impl_wasm_traits; #[cfg(target_family = "wasm")] @@ -54,6 +56,7 @@ use wasm_bindgen_utils::prelude::js_sys::BigInt; const DEFAULT_PAGE_SIZE: u16 = 100; // Limit concurrent dotrain source fetches to avoid overwhelming the subgraph/metaboard. const MAX_CONCURRENT_DOTRAIN_SOURCE_FETCHES: usize = 5; +const MAX_INFO_ORDER_INVENTORY_LOGS: usize = 50; #[derive(Serialize, Deserialize, Debug, Clone)] #[serde(rename_all = "camelCase")] @@ -185,6 +188,59 @@ fn get_io_by_type(order: &RaindexOrder, vault_type: RaindexVaultType) -> Vec Vec { + vaults + .iter() + .map(|vault| { + let vault_id = vault.vault_id_string(); + + format!( + "vault_id={},token={},balance={}", + vault_id, + vault.token().address(), + vault.formatted_balance() + ) + }) + .collect() +} + +fn log_order_inventory_for_pair( + chain_id: u32, + sell_token: Address, + buy_token: Address, + orders: &[RaindexOrder], +) { + for (order_index, order) in orders + .iter() + .take(MAX_INFO_ORDER_INVENTORY_LOGS) + .enumerate() + { + info!( + chain_id, + sell_token = %sell_token, + buy_token = %buy_token, + order_index, + order_hash = %order.order_hash(), + orderbook = %order.orderbook(), + input_vaults = ?format_order_vaults(&order.inputs), + output_vaults = ?format_order_vaults(&order.outputs), + "order considered for take-orders pair" + ); + } + + let omitted = orders.len().saturating_sub(MAX_INFO_ORDER_INVENTORY_LOGS); + if omitted > 0 { + info!( + chain_id, + sell_token = %sell_token, + buy_token = %buy_token, + logged_order_count = MAX_INFO_ORDER_INVENTORY_LOGS, + omitted_order_count = omitted, + "omitted additional order inventory logs" + ); + } +} + impl RaindexOrder { pub(crate) fn from_local_db_order( raindex_client: ClientRef, @@ -1315,6 +1371,7 @@ impl RaindexClient { sell_token: Address, buy_token: Address, ) -> Result, RaindexError> { + let started_at = Timing::now(); let filters = GetOrdersFilters { owners: vec![], active: Some(true), @@ -1329,6 +1386,24 @@ impl RaindexClient { let ids = Some(vec![chain_id]); let (local_db, local_ids, sg_ids) = self.classify_chains(ids)?; + let local_chain_ids_count = local_ids.len(); + let subgraph_chain_ids_count = sg_ids.len(); + let query_source = match (local_db.is_some(), sg_ids.is_empty()) { + (true, true) => "local_db", + (false, false) => "subgraph", + (true, false) => "mixed", + (false, true) => "none", + }; + + info!( + chain_id, + sell_token = %sell_token, + buy_token = %buy_token, + query_source, + local_chain_ids_count, + subgraph_chain_ids_count, + "fetching orders for token pair" + ); let mut all_orders = Vec::new(); @@ -1337,6 +1412,12 @@ impl RaindexClient { let result = local_source .list(Some(local_ids), &filters, None, None) .await?; + info!( + chain_id, + source = "local_db", + returned_order_count = result.orders.len(), + "fetched local orders for token pair" + ); all_orders.extend(result.orders); } @@ -1345,13 +1426,44 @@ impl RaindexClient { let result = subgraph_source .list(Some(sg_ids), &filters, None, None) .await?; + info!( + chain_id, + source = "subgraph", + returned_order_count = result.orders.len(), + "fetched subgraph orders for token pair" + ); all_orders.extend(result.orders); } if all_orders.is_empty() { + warn!( + chain_id, + sell_token = %sell_token, + buy_token = %buy_token, + query_source, + local_chain_ids_count, + subgraph_chain_ids_count, + returned_order_count = 0usize, + no_liquidity = true, + duration_ms = started_at.elapsed_ms(), + "no orders found for token pair" + ); return Err(RaindexError::NoLiquidity); } + info!( + chain_id, + sell_token = %sell_token, + buy_token = %buy_token, + query_source, + local_chain_ids_count, + subgraph_chain_ids_count, + returned_order_count = all_orders.len(), + no_liquidity = false, + duration_ms = started_at.elapsed_ms(), + "fetched orders for token pair" + ); + log_order_inventory_for_pair(chain_id, sell_token, buy_token, &all_orders); Ok(all_orders) } } diff --git a/crates/common/src/raindex_client/take_orders/approval.rs b/crates/common/src/raindex_client/take_orders/approval.rs index 62a02ab8c9..9a1c0d8bc9 100644 --- a/crates/common/src/raindex_client/take_orders/approval.rs +++ b/crates/common/src/raindex_client/take_orders/approval.rs @@ -1,9 +1,11 @@ use crate::erc20::ERC20; use crate::raindex_client::RaindexError; use crate::take_orders::{check_taker_allowance, ParsedTakeOrdersMode}; +use crate::utils::timing::Timing; use alloy::primitives::Address; use rain_math_float::Float; use std::ops::Mul; +use tracing::info; use url::Url; use super::result::build_approval_result; @@ -21,7 +23,11 @@ pub struct ApprovalCheckParams { pub async fn check_approval_needed( params: &ApprovalCheckParams, ) -> Result, RaindexError> { + let started_at = Timing::now(); let max_sell_cap = calculate_max_sell_cap(params.mode, params.price_cap)?; + let formatted_max_sell_cap = max_sell_cap + .format() + .unwrap_or_else(|_| "".to_string()); let erc20 = ERC20::new(params.rpc_urls.clone(), params.sell_token); let decimals = erc20.decimals().await?; @@ -32,7 +38,21 @@ pub async fn check_approval_needed( .await .map_err(|e| RaindexError::PreflightError(e.to_string()))?; + let duration_ms = started_at.elapsed_ms(); if allowance_result.needs_approval { + info!( + sell_token = %params.sell_token, + taker = %params.taker, + orderbook = %params.orderbook, + spender = %params.orderbook, + max_sell_cap = %formatted_max_sell_cap, + token_decimals = decimals, + required_fixed_amount = %required_u256, + current_allowance = %allowance_result.current_allowance, + approval_required = true, + duration_ms, + "approval required for take-orders calldata" + ); Ok(Some(build_approval_result( params.sell_token, params.orderbook, @@ -40,6 +60,19 @@ pub async fn check_approval_needed( decimals, )?)) } else { + info!( + sell_token = %params.sell_token, + taker = %params.taker, + orderbook = %params.orderbook, + spender = %params.orderbook, + max_sell_cap = %formatted_max_sell_cap, + token_decimals = decimals, + required_fixed_amount = %required_u256, + current_allowance = %allowance_result.current_allowance, + approval_required = false, + duration_ms, + "approval check passed" + ); Ok(None) } } diff --git a/crates/common/src/raindex_client/take_orders/mod.rs b/crates/common/src/raindex_client/take_orders/mod.rs index ed29104787..36f651d9d8 100644 --- a/crates/common/src/raindex_client/take_orders/mod.rs +++ b/crates/common/src/raindex_client/take_orders/mod.rs @@ -18,13 +18,109 @@ use super::{RaindexClient, RaindexError}; use crate::rpc_client::RpcClient; use crate::take_orders::{ build_take_orders_config_from_simulation, find_failing_order_index, simulate_take_orders, - NoopInjector, SignedContextInjector, + NoopInjector, SelectedTakeOrderLeg, SignedContextInjector, }; +use crate::utils::timing::Timing; +use alloy::primitives::{keccak256, B256}; +use alloy::sol_types::SolValue; use approval::{check_approval_needed, ApprovalCheckParams}; use rain_orderbook_bindings::provider::mk_read_provider; +use tracing::{error, info, info_span, warn, Instrument}; use wasm_bindgen_utils::prelude::*; use wasm_bindgen_utils::wasm_export; +const MAX_INFO_SELECTED_LEG_LOGS: usize = 100; + +macro_rules! emit_selected_leg { + ($level:ident, $leg_index:expr, $leg:expr, $orderbook:expr, $block_number:expr, $message:expr) => {{ + let order = &$leg.candidate.order; + let input_index = $leg.candidate.input_io_index as usize; + let output_index = $leg.candidate.output_io_index as usize; + let input = &order.validInputs[input_index]; + let output = &order.validOutputs[output_index]; + + $level!( + orderbook = %$orderbook, + block_number = $block_number, + leg_index = $leg_index, + order_hash = %order_hash_for_leg($leg), + input_io_index = $leg.candidate.input_io_index, + output_io_index = $leg.candidate.output_io_index, + input_token = %input.token, + output_token = %output.token, + input_vault_id = %input.vaultId, + output_vault_id = %output.vaultId, + selected_input = %format_float_for_log($leg.input), + selected_output = %format_float_for_log($leg.output), + ratio = %format_float_for_log($leg.candidate.ratio), + event = $message, + "take-order leg" + ); + }}; +} + +fn truncate_error(value: &str) -> String { + const MAX_LEN: usize = 512; + if value.chars().count() <= MAX_LEN { + value.to_string() + } else { + format!("{}...", value.chars().take(MAX_LEN).collect::()) + } +} + +fn format_float_for_log(value: rain_math_float::Float) -> String { + value + .format() + .unwrap_or_else(|_| "".to_string()) +} + +fn order_hash_for_leg(leg: &SelectedTakeOrderLeg) -> B256 { + B256::from(keccak256(leg.candidate.order.abi_encode())) +} + +fn log_selected_leg( + leg_index: usize, + leg: &SelectedTakeOrderLeg, + orderbook: alloy::primitives::Address, + block_number: u64, + message: &'static str, +) { + emit_selected_leg!(info, leg_index, leg, orderbook, block_number, message); +} + +fn warn_selected_leg( + leg_index: usize, + leg: &SelectedTakeOrderLeg, + orderbook: alloy::primitives::Address, + block_number: u64, + message: &'static str, +) { + emit_selected_leg!(warn, leg_index, leg, orderbook, block_number, message); +} + +fn log_selected_legs( + orderbook: alloy::primitives::Address, + block_number: u64, + legs: &[SelectedTakeOrderLeg], + message: &'static str, +) { + for (leg_index, leg) in legs.iter().take(MAX_INFO_SELECTED_LEG_LOGS).enumerate() { + log_selected_leg(leg_index, leg, orderbook, block_number, message); + } + + let omitted = legs.len().saturating_sub(MAX_INFO_SELECTED_LEG_LOGS); + if omitted > 0 { + info!( + orderbook = %orderbook, + block_number, + logged_leg_count = MAX_INFO_SELECTED_LEG_LOGS, + omitted_leg_count = omitted, + event = message, + "omitted additional take-order leg logs" + ); + } +} + #[wasm_export] impl RaindexClient { /// Generates calldata for `IRaindexV6.takeOrders4` using a mode + price-cap policy. @@ -94,15 +190,56 @@ impl RaindexClient { request: TakeOrdersRequest, injector: &dyn SignedContextInjector, ) -> Result { - let req = request::parse_request(&request)?; + let span = info_span!( + "get_take_orders_calldata", + chain_id = request.chain_id, + taker = %request.taker, + sell_token = %request.sell_token, + buy_token = %request.buy_token, + mode = ?request.mode, + amount = %request.amount, + price_cap = %request.price_cap, + ); + let result = async move { + let started_at = Timing::now(); + let req = { + let step = info_span!("take_orders.request_parsing"); + async { + let parsed = request::parse_request(&request)?; + info!( + chain_id = request.chain_id, + taker = %parsed.taker, + sell_token = %parsed.sell_token, + buy_token = %parsed.buy_token, + mode = ?parsed.mode.mode, + amount = %parsed.mode.amount.format().unwrap_or_else(|_| "".to_string()), + price_cap = %parsed.price_cap.format().unwrap_or_else(|_| "".to_string()), + "parsed take-orders request" + ); + Ok::<_, RaindexError>(parsed) + } + .instrument(step) + .await? + }; let orders = self .fetch_orders_for_pair(request.chain_id, req.sell_token, req.buy_token) + .instrument(info_span!("take_orders.fetching_orders")) .await?; + let orders_count = orders.len(); - let rpc_urls = self.get_rpc_urls_for_chain(request.chain_id)?; + let rpc_urls = { + let _span = info_span!("take_orders.resolving_rpc_urls").entered(); + let urls = self.get_rpc_urls_for_chain(request.chain_id)?; + info!(chain_id = request.chain_id, rpc_url_count = urls.len(), "resolved RPC URLs"); + urls + }; let rpc_client = RpcClient::new_with_urls(rpc_urls.clone())?; - let block_number = rpc_client.get_latest_block_number().await?; + let block_number = rpc_client + .get_latest_block_number() + .instrument(info_span!("take_orders.fetching_latest_block")) + .await?; + info!(chain_id = request.chain_id, block_number, "fetched latest block number"); let candidates = selection::build_candidates_for_chain( &orders, @@ -113,17 +250,33 @@ impl RaindexClient { req.taker, injector, ) + .instrument(info_span!("take_orders.building_candidates")) .await?; + let candidates_count = candidates.len(); - let (best_orderbook, best_sim) = selection::select_best_orderbook_simulation( - candidates.clone(), - req.mode, - req.price_cap, - )?; + let (best_orderbook, best_sim) = { + let _span = info_span!("take_orders.selecting_best_orderbook").entered(); + selection::select_best_orderbook_simulation(candidates.clone(), req.mode, req.price_cap)? + }; + let selected_legs_count = best_sim.legs.len(); - let mut built = + let mut built = { + let _span = info_span!("take_orders.building_config", orderbook = %best_orderbook).entered(); build_take_orders_config_from_simulation(best_sim.clone(), req.mode, req.price_cap)? - .ok_or(RaindexError::NoLiquidity)?; + .ok_or(RaindexError::NoLiquidity)? + }; + info!( + orderbook = %best_orderbook, + legs_count = built.sim.legs.len(), + orders_count = built.config.orders.len(), + "built take-orders config" + ); + log_selected_legs( + best_orderbook, + block_number, + &built.sim.legs, + "selected take-orders candidate leg", + ); let approval_params = ApprovalCheckParams { rpc_urls: rpc_urls.clone(), @@ -134,14 +287,32 @@ impl RaindexClient { price_cap: req.price_cap, }; - if let Some(approval_result) = check_approval_needed(&approval_params).await? { + if let Some(approval_result) = check_approval_needed(&approval_params) + .instrument(info_span!("take_orders.checking_approval", orderbook = %best_orderbook)) + .await? + { + info!( + result_type = "approval_required", + orders_count, + candidates_count, + selected_orderbook = %best_orderbook, + selected_legs_count, + block_number, + preflight_iterations = 0usize, + removed_orders_count = 0usize, + duration_ms = started_at.elapsed_ms(), + "take-orders calldata requires approval" + ); return Ok(approval_result); } let provider = mk_read_provider(&rpc_urls).map_err(|e| RaindexError::PreflightError(e.to_string()))?; - for _ in 0..built.config.orders.len() { + let mut removed_orders_count = 0usize; + let max_iterations = built.config.orders.len(); + for iteration in 0..max_iterations { + let iteration_started_at = Timing::now(); let sim_result = simulate_take_orders( &provider, best_orderbook, @@ -149,10 +320,36 @@ impl RaindexClient { &built.config, Some(block_number), ) + .instrument(info_span!( + "take_orders.preflight_iteration", + orderbook = %best_orderbook, + taker = %req.taker, + block_number, + orders_count = built.config.orders.len(), + iteration + )) .await; match sim_result { Ok(()) => { + log_selected_legs( + best_orderbook, + block_number, + &built.sim.legs, + "final take-orders transaction leg", + ); + info!( + result_type = "take_orders", + orders_count, + candidates_count, + selected_orderbook = %best_orderbook, + selected_legs_count = built.sim.legs.len(), + block_number, + preflight_iterations = iteration + 1, + removed_orders_count, + duration_ms = started_at.elapsed_ms(), + "take-orders calldata ready" + ); return result::build_calldata_result( best_orderbook, built, @@ -161,6 +358,16 @@ impl RaindexClient { ); } Err(sim_error) => { + warn!( + orderbook = %best_orderbook, + taker = %req.taker, + block_number, + orders_count = built.config.orders.len(), + iteration, + error = %truncate_error(&sim_error), + duration_ms = iteration_started_at.elapsed_ms(), + "preflight simulation failed" + ); if let Some(failing_idx) = find_failing_order_index( &provider, best_orderbook, @@ -168,18 +375,58 @@ impl RaindexClient { &built.config, Some(block_number), ) + .instrument(info_span!( + "take_orders.find_failing_order", + orderbook = %best_orderbook, + taker = %req.taker, + block_number, + order_count = built.config.orders.len(), + iteration + )) .await { if built.config.orders.len() <= 1 { + error!( + orderbook = %best_orderbook, + iteration, + failing_order_index = failing_idx, + error = %truncate_error(&sim_error), + "all orders failed preflight simulation" + ); return Err(RaindexError::PreflightError(format!( "All orders failed simulation. Last error: {}", sim_error ))); } + if let Some(failing_leg) = built.sim.legs.get(failing_idx) { + warn_selected_leg( + failing_idx, + failing_leg, + best_orderbook, + block_number, + "removed failing preflight leg", + ); + } + built.config.orders.remove(failing_idx); built.sim.legs.remove(failing_idx); + removed_orders_count += 1; + warn!( + orderbook = %best_orderbook, + iteration, + failing_order_index = failing_idx, + orders_remaining = built.config.orders.len(), + removed_orders_count, + "removed failing order after preflight" + ); } else { + error!( + orderbook = %best_orderbook, + iteration, + error = %truncate_error(&sim_error), + "preflight failed without identifiable order" + ); return Err(RaindexError::PreflightError(format!( "Simulation failed but could not identify failing order: {}", sim_error @@ -189,9 +436,19 @@ impl RaindexClient { } } - Err(RaindexError::PreflightError( - "Exceeded maximum preflight iterations".to_string(), - )) + error!( + orderbook = %best_orderbook, + max_iterations, + removed_orders_count, + "exceeded maximum preflight iterations" + ); + Err(RaindexError::PreflightError( + "Exceeded maximum preflight iterations".to_string(), + )) + } + .instrument(span) + .await; + result } } diff --git a/crates/common/src/raindex_client/take_orders/selection.rs b/crates/common/src/raindex_client/take_orders/selection.rs index 7523240ad9..1b2389b1f9 100644 --- a/crates/common/src/raindex_client/take_orders/selection.rs +++ b/crates/common/src/raindex_client/take_orders/selection.rs @@ -6,9 +6,17 @@ use crate::take_orders::{ TakeOrderCandidate, }; use crate::utils::float::cmp_float; +use crate::utils::timing::Timing; use alloy::primitives::Address; use rain_math_float::Float; use std::collections::HashMap; +use tracing::{debug, info, warn}; + +fn format_float(value: Float) -> String { + value + .format() + .unwrap_or_else(|_| "".to_string()) +} pub(crate) async fn build_candidates_for_chain( orders: &[RaindexOrder], @@ -19,6 +27,7 @@ pub(crate) async fn build_candidates_for_chain( counterparty: Address, injector: &dyn SignedContextInjector, ) -> Result, RaindexError> { + let started_at = Timing::now(); let candidates = build_take_order_candidates_for_pair( orders, sell_token, @@ -30,8 +39,24 @@ pub(crate) async fn build_candidates_for_chain( ) .await?; if candidates.is_empty() { + warn!( + sell_token = %sell_token, + buy_token = %buy_token, + orders_count = orders.len(), + candidates_count = 0usize, + duration_ms = started_at.elapsed_ms(), + "no take-order candidates available" + ); return Err(RaindexError::NoLiquidity); } + info!( + sell_token = %sell_token, + buy_token = %buy_token, + orders_count = orders.len(), + candidates_count = candidates.len(), + duration_ms = started_at.elapsed_ms(), + "built take-order candidates for chain" + ); Ok(candidates) } @@ -56,6 +81,8 @@ pub(crate) fn select_best_orderbook_simulation( mode: ParsedTakeOrdersMode, price_cap: Float, ) -> Result<(Address, SimulationResult), RaindexError> { + let started_at = Timing::now(); + let total_candidate_count = candidates.len(); let mut orderbook_candidates: HashMap> = HashMap::new(); for candidate in candidates { orderbook_candidates @@ -68,8 +95,18 @@ pub(crate) fn select_best_orderbook_simulation( let is_buy_mode = mode.is_buy_mode(); let mut best_result: Option<(Address, SimulationResult)> = None; + let orderbook_count = orderbook_candidates.len(); + let mut skipped_empty_sims = 0usize; + info!( + orderbook_count, + total_candidate_count, + mode = ?mode.mode, + "selecting best orderbook simulation" + ); for (orderbook, candidates) in orderbook_candidates { + let candidate_count = candidates.len(); + info!(orderbook = %orderbook, candidate_count, "simulating orderbook candidates"); let sim = if is_buy_mode { simulate_buy_over_candidates(candidates, target, price_cap)? } else { @@ -77,10 +114,19 @@ pub(crate) fn select_best_orderbook_simulation( }; if sim.legs.is_empty() { + skipped_empty_sims += 1; + info!(orderbook = %orderbook, candidate_count, "skipping orderbook with empty simulation"); continue; } let achieved = sim.total_output; + debug!( + orderbook = %orderbook, + legs_count = sim.legs.len(), + total_input = %format_float(sim.total_input), + total_output = %format_float(sim.total_output), + "orderbook simulation achieved output" + ); let is_better = match &best_result { None => true, @@ -94,8 +140,15 @@ pub(crate) fn select_best_orderbook_simulation( let best_worst = worst_price(best_sim)?; match (sim_worst, best_worst) { (Some(sw), Some(bw)) => match cmp_float(&sw, &bw)? { - std::cmp::Ordering::Less => true, - std::cmp::Ordering::Equal => orderbook < *best_addr, + std::cmp::Ordering::Less => { + debug!(orderbook = %orderbook, best_orderbook = %best_addr, "tie-break selected lower worst price"); + true + } + std::cmp::Ordering::Equal => { + let wins = orderbook < *best_addr; + debug!(orderbook = %orderbook, best_orderbook = %best_addr, selected = wins, "tie-break compared orderbook address"); + wins + } std::cmp::Ordering::Greater => false, }, _ => orderbook < *best_addr, @@ -111,7 +164,32 @@ pub(crate) fn select_best_orderbook_simulation( } } - best_result.ok_or(RaindexError::NoLiquidity) + match best_result { + Some((selected_orderbook, selected_sim)) => { + info!( + orderbook_count, + total_candidate_count, + skipped_empty_sims, + selected_orderbook = %selected_orderbook, + selected_total_input = %format_float(selected_sim.total_input), + selected_total_output = %format_float(selected_sim.total_output), + selected_legs_count = selected_sim.legs.len(), + duration_ms = started_at.elapsed_ms(), + "selected best orderbook simulation" + ); + Ok((selected_orderbook, selected_sim)) + } + None => { + warn!( + orderbook_count, + total_candidate_count, + skipped_empty_sims, + duration_ms = started_at.elapsed_ms(), + "no orderbook simulation produced liquidity" + ); + Err(RaindexError::NoLiquidity) + } + } } #[cfg(test)] diff --git a/crates/common/src/raindex_client/vaults.rs b/crates/common/src/raindex_client/vaults.rs index 48bede38a4..856c574c1a 100644 --- a/crates/common/src/raindex_client/vaults.rs +++ b/crates/common/src/raindex_client/vaults.rs @@ -118,6 +118,12 @@ pub struct RaindexVault { orders_as_outputs: Vec, } +impl RaindexVault { + pub(crate) fn vault_id_string(&self) -> String { + self.vault_id.to_string() + } +} + #[cfg(target_family = "wasm")] #[wasm_bindgen] impl RaindexVault { diff --git a/crates/common/src/take_orders/candidates.rs b/crates/common/src/take_orders/candidates.rs index ef2bee1d59..ada16139af 100644 --- a/crates/common/src/take_orders/candidates.rs +++ b/crates/common/src/take_orders/candidates.rs @@ -3,12 +3,18 @@ use crate::raindex_client::order_quotes::{ }; use crate::raindex_client::orders::RaindexOrder; use crate::raindex_client::RaindexError; -use alloy::primitives::Address; +use crate::utils::timing::Timing; +use alloy::primitives::{keccak256, Address, B256}; +use alloy::sol_types::SolValue; use rain_math_float::Float; use rain_orderbook_bindings::IRaindexV6::{OrderV4, SignedContextV1}; use rain_orderbook_quote::SignedContextInjector; #[cfg(target_family = "wasm")] use std::str::FromStr; +use tracing::{debug, enabled, info, Level}; + +const MAX_INFO_CANDIDATE_DECISION_LOGS: usize = 100; +const MAX_LOGGED_ERROR_CHARS: usize = 512; fn indices_in_bounds(order: &OrderV4, input_index: u32, output_index: u32) -> bool { (input_index as usize) < order.validInputs.len() @@ -33,6 +39,30 @@ fn has_capacity( Ok(data.max_output.gt(Float::zero()?)?) } +fn format_float(value: Float) -> String { + value + .format() + .unwrap_or_else(|_| "".to_string()) +} + +fn order_hash(order: &OrderV4) -> B256 { + B256::from(keccak256(order.abi_encode())) +} + +fn truncate_error(value: &str) -> String { + if value.chars().count() <= MAX_LOGGED_ERROR_CHARS { + value.to_string() + } else { + format!( + "{}...", + value + .chars() + .take(MAX_LOGGED_ERROR_CHARS) + .collect::() + ) + } +} + #[derive(Clone, Debug)] pub struct TakeOrderCandidate { pub orderbook: Address, @@ -50,6 +80,111 @@ pub struct TakeOrderCandidate { pub signed_context: Vec, } +#[derive(Default)] +struct CandidateBuildStats { + quote_count: usize, + quote_failures: usize, + skipped_missing_data: usize, + skipped_out_of_bounds_io_indices: usize, + skipped_wrong_direction: usize, + skipped_zero_or_non_positive_capacity: usize, + info_rejection_logs: usize, + omitted_info_rejection_logs: usize, +} + +struct CandidateDecisionLog<'a> { + stats: &'a mut CandidateBuildStats, + orderbook: Address, + order: &'a OrderV4, + quote: &'a RaindexOrderQuote, + requested_input_token: Address, + requested_output_token: Address, + decision: &'static str, + reason: &'static str, +} + +fn log_candidate_decision(params: CandidateDecisionLog<'_>) { + let CandidateDecisionLog { + stats, + orderbook, + order, + quote, + requested_input_token, + requested_output_token, + decision, + reason, + } = params; + + let is_accepted = decision == "accepted"; + if is_accepted { + if !enabled!(Level::DEBUG) { + return; + } + } else if stats.info_rejection_logs >= MAX_INFO_CANDIDATE_DECISION_LOGS { + stats.omitted_info_rejection_logs += 1; + return; + } + + let input = order.validInputs.get(quote.pair.input_index as usize); + let output = order.validOutputs.get(quote.pair.output_index as usize); + let quoted_max_output = quote + .data + .as_ref() + .map(|data| format_float(data.max_output)) + .unwrap_or_else(|| "none".to_string()); + let quoted_ratio = quote + .data + .as_ref() + .map(|data| format_float(data.ratio)) + .unwrap_or_else(|| "none".to_string()); + let quote_error = quote.error.as_deref().map(truncate_error); + + if is_accepted { + debug!( + orderbook = %orderbook, + order_hash = %order_hash(order), + input_io_index = quote.pair.input_index, + output_io_index = quote.pair.output_index, + input_token = %input.map(|io| io.token).unwrap_or(Address::ZERO), + output_token = %output.map(|io| io.token).unwrap_or(Address::ZERO), + input_vault_id = %input.map(|io| io.vaultId).unwrap_or_default(), + output_vault_id = %output.map(|io| io.vaultId).unwrap_or_default(), + requested_input_token = %requested_input_token, + requested_output_token = %requested_output_token, + quote_success = quote.success, + quote_error = ?quote_error, + quoted_max_output = %quoted_max_output, + quoted_ratio = %quoted_ratio, + signed_context_count = quote.signed_context.len(), + decision, + reason, + "take-order candidate decision" + ); + } else { + info!( + orderbook = %orderbook, + order_hash = %order_hash(order), + input_io_index = quote.pair.input_index, + output_io_index = quote.pair.output_index, + input_token = %input.map(|io| io.token).unwrap_or(Address::ZERO), + output_token = %output.map(|io| io.token).unwrap_or(Address::ZERO), + input_vault_id = %input.map(|io| io.vaultId).unwrap_or_default(), + output_vault_id = %output.map(|io| io.vaultId).unwrap_or_default(), + requested_input_token = %requested_input_token, + requested_output_token = %requested_output_token, + quote_success = quote.success, + quote_error = ?quote_error, + quoted_max_output = %quoted_max_output, + quoted_ratio = %quoted_ratio, + signed_context_count = quote.signed_context.len(), + decision, + reason, + "take-order candidate decision" + ); + stats.info_rejection_logs += 1; + } +} + fn get_orderbook_address(order: &RaindexOrder) -> Result { #[cfg(target_family = "wasm")] { @@ -70,6 +205,7 @@ pub async fn build_take_order_candidates_for_pair( counterparty: Address, injector: &dyn SignedContextInjector, ) -> Result, RaindexError> { + let started_at = Timing::now(); // Oracle fetch and injector invocation both happen inside the quote // pipeline now: `get_order_quotes_batch_with_injector` composes them into // `QuoteV2.signedContext` before issuing the quote RPC, so gated orders @@ -86,19 +222,44 @@ pub async fn build_take_order_candidates_for_pair( .await?; let mut all_candidates = vec![]; + let mut stats = CandidateBuildStats::default(); for (order, quotes) in orders.iter().zip(all_quotes) { let order_v4: OrderV4 = order.try_into()?; let orderbook = get_orderbook_address(order)?; for quote in "es { - if let Some(candidate) = - try_build_candidate(orderbook, &order_v4, quote, input_token, output_token)? - { + stats.quote_count += 1; + if let Some(candidate) = try_build_candidate( + orderbook, + &order_v4, + quote, + input_token, + output_token, + &mut stats, + )? { all_candidates.push(candidate); } } } + info!( + input_order_count = orders.len(), + quote_count = stats.quote_count, + candidate_count = all_candidates.len(), + quote_failures = stats.quote_failures, + skipped_missing_data = stats.skipped_missing_data, + skipped_out_of_bounds_io_indices = stats.skipped_out_of_bounds_io_indices, + skipped_wrong_direction = stats.skipped_wrong_direction, + skipped_zero_or_non_positive_capacity = stats.skipped_zero_or_non_positive_capacity, + info_rejection_logs = stats.info_rejection_logs, + omitted_info_rejection_logs = stats.omitted_info_rejection_logs, + input_token = %input_token, + output_token = %output_token, + block_number = ?block_number, + duration_ms = started_at.elapsed_ms(), + "built take-order candidates for pair" + ); + Ok(all_candidates) } @@ -108,16 +269,69 @@ fn try_build_candidate( quote: &RaindexOrderQuote, input_token: Address, output_token: Address, + stats: &mut CandidateBuildStats, ) -> Result, RaindexError> { let data = match (quote.success, "e.data) { (true, Some(d)) => d, - _ => return Ok(None), + (false, _) => { + stats.quote_failures += 1; + log_candidate_decision(CandidateDecisionLog { + stats, + orderbook, + order, + quote, + requested_input_token: input_token, + requested_output_token: output_token, + decision: "rejected", + reason: "quote_failed", + }); + debug!( + orderbook = %orderbook, + input_index = quote.pair.input_index, + output_index = quote.pair.output_index, + error = ?quote.error, + "skipping failed quote" + ); + return Ok(None); + } + (true, None) => { + stats.skipped_missing_data += 1; + log_candidate_decision(CandidateDecisionLog { + stats, + orderbook, + order, + quote, + requested_input_token: input_token, + requested_output_token: output_token, + decision: "rejected", + reason: "missing_quote_data", + }); + debug!( + orderbook = %orderbook, + input_index = quote.pair.input_index, + output_index = quote.pair.output_index, + "skipping quote with missing data" + ); + return Ok(None); + } }; let input_io_index = quote.pair.input_index; let output_io_index = quote.pair.output_index; if !indices_in_bounds(order, input_io_index, output_io_index) { + stats.skipped_out_of_bounds_io_indices += 1; + log_candidate_decision(CandidateDecisionLog { + stats, + orderbook, + order, + quote, + requested_input_token: input_token, + requested_output_token: output_token, + decision: "rejected", + reason: "out_of_bounds_io_indices", + }); + debug!(orderbook = %orderbook, input_io_index, output_io_index, "skipping quote with out-of-bounds IO indices"); return Ok(None); } @@ -128,13 +342,48 @@ fn try_build_candidate( input_token, output_token, ) { + stats.skipped_wrong_direction += 1; + log_candidate_decision(CandidateDecisionLog { + stats, + orderbook, + order, + quote, + requested_input_token: input_token, + requested_output_token: output_token, + decision: "rejected", + reason: "wrong_direction", + }); + debug!(orderbook = %orderbook, input_io_index, output_io_index, "skipping quote with wrong direction"); return Ok(None); } if !has_capacity(data)? { + stats.skipped_zero_or_non_positive_capacity += 1; + log_candidate_decision(CandidateDecisionLog { + stats, + orderbook, + order, + quote, + requested_input_token: input_token, + requested_output_token: output_token, + decision: "rejected", + reason: "zero_or_non_positive_capacity", + }); + debug!(orderbook = %orderbook, input_io_index, output_io_index, "skipping quote with zero or non-positive capacity"); return Ok(None); } + log_candidate_decision(CandidateDecisionLog { + stats, + orderbook, + order, + quote, + requested_input_token: input_token, + requested_output_token: output_token, + decision: "accepted", + reason: "eligible", + }); + // Defer clone until the candidate survives all filters. Ok(Some(TakeOrderCandidate { orderbook, @@ -269,7 +518,15 @@ mod tests { let f1 = Float::parse("1".to_string()).unwrap(); let quote = make_quote(0, 0, Some(make_quote_value(f1, f1, f1)), true); - let result = try_build_candidate(orderbook, &order, "e, token_b, token_a).unwrap(); + let result = try_build_candidate( + orderbook, + &order, + "e, + token_b, + token_a, + &mut CandidateBuildStats::default(), + ) + .unwrap(); assert!(result.is_none()); } @@ -285,7 +542,15 @@ mod tests { let f1 = Float::parse("1".to_string()).unwrap(); let quote = make_quote(0, 0, Some(make_quote_value(zero, zero, f1)), true); - let result = try_build_candidate(orderbook, &order, "e, token_a, token_b).unwrap(); + let result = try_build_candidate( + orderbook, + &order, + "e, + token_a, + token_b, + &mut CandidateBuildStats::default(), + ) + .unwrap(); assert!(result.is_none()); } @@ -301,7 +566,15 @@ mod tests { let f2 = Float::parse("2".to_string()).unwrap(); let quote = make_quote(0, 0, Some(make_quote_value(f2, f1, f1)), true); - let result = try_build_candidate(orderbook, &order, "e, token_a, token_b).unwrap(); + let result = try_build_candidate( + orderbook, + &order, + "e, + token_a, + token_b, + &mut CandidateBuildStats::default(), + ) + .unwrap(); assert!(result.is_some()); let candidate = result.unwrap(); @@ -320,7 +593,14 @@ mod tests { let order = make_basic_order(token_a, token_b); let quote = make_quote(0, 0, None, false); - let result = try_build_candidate(orderbook, &order, "e, token_a, token_b); + let result = try_build_candidate( + orderbook, + &order, + "e, + token_a, + token_b, + &mut CandidateBuildStats::default(), + ); assert!( result.is_ok(), @@ -373,9 +653,16 @@ mod tests { let mut quote = make_quote(0, 0, Some(make_quote_value(f2, f1, f1)), true); quote.signed_context = vec![oracle_entry.clone(), injected_entry.clone()]; - let result = try_build_candidate(orderbook, &order, "e, token_a, token_b) - .unwrap() - .expect("candidate should be built"); + let result = try_build_candidate( + orderbook, + &order, + "e, + token_a, + token_b, + &mut CandidateBuildStats::default(), + ) + .unwrap() + .expect("candidate should be built"); assert_eq!(result.signed_context.len(), 2); assert_eq!(result.signed_context[0].signer, oracle_entry.signer); @@ -392,8 +679,14 @@ mod tests { let f1 = Float::parse("1".to_string()).unwrap(); let quote_bad_input_index = make_quote(99, 0, Some(make_quote_value(f1, f1, f1)), true); - let result = - try_build_candidate(orderbook, &order, "e_bad_input_index, token_a, token_b); + let result = try_build_candidate( + orderbook, + &order, + "e_bad_input_index, + token_a, + token_b, + &mut CandidateBuildStats::default(), + ); assert!( result.is_ok(), "Out-of-bounds input index must not cause an error" @@ -404,8 +697,14 @@ mod tests { ); let quote_bad_output_index = make_quote(0, 99, Some(make_quote_value(f1, f1, f1)), true); - let result = - try_build_candidate(orderbook, &order, "e_bad_output_index, token_a, token_b); + let result = try_build_candidate( + orderbook, + &order, + "e_bad_output_index, + token_a, + token_b, + &mut CandidateBuildStats::default(), + ); assert!( result.is_ok(), "Out-of-bounds output index must not cause an error" diff --git a/crates/common/src/take_orders/preflight.rs b/crates/common/src/take_orders/preflight.rs index 68863eda22..f599faf1e3 100644 --- a/crates/common/src/take_orders/preflight.rs +++ b/crates/common/src/take_orders/preflight.rs @@ -1,3 +1,4 @@ +use crate::utils::timing::Timing; use alloy::network::TransactionBuilder; use alloy::primitives::{Address, Bytes, U256}; use alloy::providers::Provider; @@ -8,6 +9,7 @@ use rain_orderbook_bindings::provider::ReadProvider; use rain_orderbook_bindings::IRaindexV6::{takeOrders4Call, TakeOrdersConfigV5}; use rain_orderbook_bindings::IERC20::approveCall; use thiserror::Error; +use tracing::{debug, info, warn}; use crate::erc20::ERC20; @@ -151,6 +153,15 @@ pub async fn simulate_take_orders( config: &TakeOrdersConfigV5, block_number: Option, ) -> Result<(), String> { + let started_at = Timing::now(); + let order_count = config.orders.len(); + debug!( + orderbook = %orderbook, + taker = %taker, + block_number = ?block_number, + order_count, + "starting take-orders preflight simulation" + ); let calldata = takeOrders4Call { config: config.clone(), } @@ -173,8 +184,32 @@ pub async fn simulate_take_orders( .await; match result { - Ok(_) => Ok(()), - Err(e) => Err(e.to_string()), + Ok(_) => { + info!( + orderbook = %orderbook, + taker = %taker, + block_number = ?block_number, + order_count, + simulation_success = true, + duration_ms = started_at.elapsed_ms(), + "take-orders preflight simulation succeeded" + ); + Ok(()) + } + Err(e) => { + let error = e.to_string(); + warn!( + orderbook = %orderbook, + taker = %taker, + block_number = ?block_number, + order_count, + simulation_success = false, + error = %error.chars().take(512).collect::(), + duration_ms = started_at.elapsed_ms(), + "take-orders preflight simulation failed" + ); + Err(error) + } } } @@ -185,18 +220,30 @@ pub async fn find_failing_order_index( config: &TakeOrdersConfigV5, block_number: Option, ) -> Option { + let started_at = Timing::now(); if config.orders.is_empty() { + debug!(orderbook = %orderbook, "cannot find failing order in empty config"); return None; } if config.orders.len() == 1 { let result = simulate_take_orders(provider, orderbook, taker, config, block_number).await; if result.is_err() { + warn!( + orderbook = %orderbook, + taker = %taker, + block_number = ?block_number, + failing_order_index = 0usize, + simulations_run = 1usize, + duration_ms = started_at.elapsed_ms(), + "identified failing order" + ); return Some(0); } return None; } + let mut simulations_run = 0usize; for idx in 0..config.orders.len() { let single_order_config = TakeOrdersConfigV5 { minimumIO: config.minimumIO, @@ -215,12 +262,30 @@ pub async fn find_failing_order_index( block_number, ) .await; + simulations_run += 1; if result.is_err() { + warn!( + orderbook = %orderbook, + taker = %taker, + block_number = ?block_number, + failing_order_index = idx, + simulations_run, + duration_ms = started_at.elapsed_ms(), + "identified failing order" + ); return Some(idx); } } + warn!( + orderbook = %orderbook, + taker = %taker, + block_number = ?block_number, + simulations_run, + duration_ms = started_at.elapsed_ms(), + "could not identify failing order" + ); None } diff --git a/crates/common/src/take_orders/simulation.rs b/crates/common/src/take_orders/simulation.rs index bfc6cc61ce..2d0fd8f803 100644 --- a/crates/common/src/take_orders/simulation.rs +++ b/crates/common/src/take_orders/simulation.rs @@ -1,10 +1,26 @@ use super::candidates::TakeOrderCandidate; use crate::raindex_client::RaindexError; use crate::utils::float::cmp_float; +use crate::utils::timing::Timing; +use alloy::primitives::{keccak256, B256}; +use alloy::sol_types::SolValue; use rain_math_float::Float; use std::cell::RefCell; use std::cmp::Ordering; use std::ops::{Add, Div, Mul, Sub}; +use tracing::info; + +const MAX_INFO_PRICE_CAP_REJECTION_LOGS: usize = 100; + +fn format_float(value: Float) -> String { + value + .format() + .unwrap_or_else(|_| "".to_string()) +} + +fn order_hash(candidate: &TakeOrderCandidate) -> B256 { + B256::from(keccak256(candidate.order.abi_encode())) +} #[derive(Clone, Debug)] pub struct SelectedTakeOrderLeg { @@ -143,22 +159,41 @@ fn filter_candidates_by_price_cap( candidates: Vec, price_cap: Float, ) -> Result, RaindexError> { - Ok(candidates - .into_iter() - .filter_map(|candidate| { - let ratio = candidate.ratio; - match ratio.lte(price_cap) { - Ok(is_below_cap) => { - if is_below_cap { - Some(Ok(candidate)) - } else { - None - } - } - Err(e) => Some(Err(e)), - } - }) - .collect::, _>>()?) + let mut filtered = Vec::new(); + let mut logged_rejections = 0usize; + let mut omitted_rejections = 0usize; + + for candidate in candidates { + let ratio = candidate.ratio; + if ratio.lte(price_cap)? { + filtered.push(candidate); + } else if logged_rejections < MAX_INFO_PRICE_CAP_REJECTION_LOGS { + info!( + orderbook = %candidate.orderbook, + order_hash = %order_hash(&candidate), + input_io_index = candidate.input_io_index, + output_io_index = candidate.output_io_index, + max_output = %format_float(candidate.max_output), + ratio = %format_float(candidate.ratio), + price_cap = %format_float(price_cap), + decision = "rejected", + reason = "above_price_cap", + "take-order candidate decision" + ); + logged_rejections += 1; + } else { + omitted_rejections += 1; + } + } + + if omitted_rejections > 0 { + info!( + logged_rejections, + omitted_rejections, "omitted additional price-cap candidate rejection logs" + ); + } + + Ok(filtered) } pub fn simulate_buy_over_candidates( @@ -166,7 +201,10 @@ pub fn simulate_buy_over_candidates( buy_target: Float, price_cap: Float, ) -> Result { + let started_at = Timing::now(); + let initial_candidate_count = candidates.len(); let mut filtered = filter_candidates_by_price_cap(candidates, price_cap)?; + let filtered_candidate_count = filtered.len(); sort_candidates_by_price(&mut filtered)?; let zero = Float::zero()?; @@ -188,11 +226,28 @@ pub fn simulate_buy_over_candidates( } } - Ok(SimulationResult { + let result = SimulationResult { legs, total_input: totals.total_input, total_output: totals.total_output, - }) + }; + info!( + mode = "buy", + initial_candidate_count, + candidates_after_price_cap = filtered_candidate_count, + selected_legs_count = result.legs.len(), + total_input = %format_float(result.total_input), + total_output = %format_float(result.total_output), + fully_filled = result.total_output.eq(buy_target).unwrap_or(false), + worst_selected_ratio = %result + .legs + .last() + .map(|leg| format_float(leg.candidate.ratio)) + .unwrap_or_else(|| "none".to_string()), + duration_ms = started_at.elapsed_ms(), + "simulated buy over candidates" + ); + Ok(result) } pub fn simulate_spend_over_candidates( @@ -200,7 +255,10 @@ pub fn simulate_spend_over_candidates( spend_budget: Float, price_cap: Float, ) -> Result { + let started_at = Timing::now(); + let initial_candidate_count = candidates.len(); let mut filtered = filter_candidates_by_price_cap(candidates, price_cap)?; + let filtered_candidate_count = filtered.len(); sort_candidates_by_price(&mut filtered)?; let zero = Float::zero()?; @@ -222,11 +280,28 @@ pub fn simulate_spend_over_candidates( } } - Ok(SimulationResult { + let result = SimulationResult { legs, total_input: totals.total_input, total_output: totals.total_output, - }) + }; + info!( + mode = "spend", + initial_candidate_count, + candidates_after_price_cap = filtered_candidate_count, + selected_legs_count = result.legs.len(), + total_input = %format_float(result.total_input), + total_output = %format_float(result.total_output), + fully_filled = result.total_input.eq(spend_budget).unwrap_or(false), + worst_selected_ratio = %result + .legs + .last() + .map(|leg| format_float(leg.candidate.ratio)) + .unwrap_or_else(|| "none".to_string()), + duration_ms = started_at.elapsed_ms(), + "simulated spend over candidates" + ); + Ok(result) } #[cfg(test)] diff --git a/crates/common/src/utils/mod.rs b/crates/common/src/utils/mod.rs index 77db7faa28..1dd3ad223b 100644 --- a/crates/common/src/utils/mod.rs +++ b/crates/common/src/utils/mod.rs @@ -2,3 +2,4 @@ pub mod amount_formatter; pub mod float; pub mod serde; pub mod timestamp; +pub mod timing; diff --git a/crates/common/src/utils/timing.rs b/crates/common/src/utils/timing.rs new file mode 100644 index 0000000000..d566757155 --- /dev/null +++ b/crates/common/src/utils/timing.rs @@ -0,0 +1,37 @@ +#[cfg(target_family = "wasm")] +use wasm_bindgen_utils::prelude::js_sys::Date; + +pub struct Timing { + #[cfg(not(target_family = "wasm"))] + started_at: std::time::Instant, + #[cfg(target_family = "wasm")] + started_at_ms: f64, +} + +impl Timing { + pub fn now() -> Self { + Self { + #[cfg(not(target_family = "wasm"))] + started_at: std::time::Instant::now(), + #[cfg(target_family = "wasm")] + started_at_ms: Date::now(), + } + } + + pub fn elapsed_ms(&self) -> u64 { + #[cfg(not(target_family = "wasm"))] + { + self.started_at.elapsed().as_millis() as u64 + } + + #[cfg(target_family = "wasm")] + { + let elapsed = Date::now() - self.started_at_ms; + if elapsed.is_finite() && elapsed > 0.0 { + elapsed as u64 + } else { + 0 + } + } + } +}