diff --git a/Cargo.lock b/Cargo.lock index b3f236410..3fe6a6738 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -3555,6 +3555,7 @@ dependencies = [ "magicblock-config", "magicblock-core", "magicblock-ledger", + "magicblock-metrics", "magicblock-version", "parking_lot 0.12.4", "rand 0.9.1", @@ -3859,6 +3860,7 @@ dependencies = [ "magicblock-accounts-db", "magicblock-core", "magicblock-ledger", + "magicblock-metrics", "magicblock-program", "parking_lot 0.12.4", "solana-account", diff --git a/Cargo.toml b/Cargo.toml index fa58bda4a..b7c9686d8 100644 --- a/Cargo.toml +++ b/Cargo.toml @@ -91,7 +91,7 @@ jsonrpc-pubsub = "18.0.0" jsonrpc-ws-server = "18.0.0" lazy_static = "1.4.0" libc = "0.2.153" -log = "0.4.20" +log = { version = "0.4.20", features = ["release_max_level_info"] } lru = "0.16.0" macrotest = "1" magic-domain-program = { git = "https://github.com/magicblock-labs/magic-domain-program.git", rev = "ea04d46", default-features = false } diff --git a/magicblock-aperture/Cargo.toml b/magicblock-aperture/Cargo.toml index 83fe9f1e5..50ce6c6db 100644 --- a/magicblock-aperture/Cargo.toml +++ b/magicblock-aperture/Cargo.toml @@ -33,6 +33,7 @@ magicblock-chainlink = { workspace = true } magicblock-config = { workspace = true } magicblock-core = { workspace = true } magicblock-ledger = { workspace = true } +magicblock-metrics = { workspace = true } magicblock-version = { workspace = true } # solana diff --git a/magicblock-aperture/src/requests/http/mod.rs b/magicblock-aperture/src/requests/http/mod.rs index cd2817653..4c1897edd 100644 --- a/magicblock-aperture/src/requests/http/mod.rs +++ b/magicblock-aperture/src/requests/http/mod.rs @@ -10,6 +10,7 @@ use log::*; use magicblock_core::{ link::transactions::SanitizeableTransaction, traits::AccountsBank, }; +use magicblock_metrics::metrics::ENSURE_ACCOUNTS_TIME; use prelude::JsonBody; use solana_account::AccountSharedData; use solana_pubkey::Pubkey; @@ -101,7 +102,9 @@ impl HttpDispatcher { &self, pubkey: &Pubkey, ) -> Option { - debug!("Ensuring account {pubkey}"); + let _timer = ENSURE_ACCOUNTS_TIME + .with_label_values(&["account"]) + .start_timer(); let _ = self .chainlink .ensure_accounts(&[*pubkey], None) @@ -109,7 +112,7 @@ impl HttpDispatcher { .inspect_err(|e| { // There is nothing we can do if fetching the account fails // Log the error and return whatever is in the accounts db - error!("Failed to ensure account {pubkey}: {e}"); + warn!("Failed to ensure account {pubkey}: {e}"); }); self.accountsdb.get_account(pubkey) } @@ -120,14 +123,10 @@ impl HttpDispatcher { &self, pubkeys: &[Pubkey], ) -> Vec> { - if log::log_enabled!(log::Level::Debug) { - let pubkeys = pubkeys - .iter() - .map(ToString::to_string) - .collect::>() - .join(", "); - debug!("Ensuring accounts {pubkeys}"); - } + trace!("Ensuring accounts {pubkeys:?}"); + let _timer = ENSURE_ACCOUNTS_TIME + .with_label_values(&["multi-account"]) + .start_timer(); let _ = self .chainlink .ensure_accounts(pubkeys, None) @@ -135,7 +134,7 @@ impl HttpDispatcher { .inspect_err(|e| { // There is nothing we can do if fetching the accounts fails // Log the error and return whatever is in the accounts db - error!("Failed to ensure accounts: {e}"); + warn!("Failed to ensure accounts: {e}"); }); pubkeys .iter() @@ -195,6 +194,9 @@ impl HttpDispatcher { &self, transaction: &SanitizedTransaction, ) -> RpcResult<()> { + let _timer = ENSURE_ACCOUNTS_TIME + .with_label_values(&["transaction"]) + .start_timer(); match self .chainlink .ensure_transaction_accounts(transaction) diff --git a/magicblock-aperture/src/requests/http/send_transaction.rs b/magicblock-aperture/src/requests/http/send_transaction.rs index d9f229b37..9b6b1da71 100644 --- a/magicblock-aperture/src/requests/http/send_transaction.rs +++ b/magicblock-aperture/src/requests/http/send_transaction.rs @@ -1,4 +1,7 @@ -use log::*; +use log::{trace, warn}; +use magicblock_metrics::metrics::{ + TRANSACTION_PROCESSING_TIME, TRANSACTION_SKIP_PREFLIGHT, +}; use solana_rpc_client_api::config::RpcSendTransactionConfig; use solana_transaction_error::TransactionError; use solana_transaction_status::UiTransactionEncoding; @@ -15,8 +18,10 @@ impl HttpDispatcher { &self, request: &mut JsonRequest, ) -> HandlerResult { + let _timer = TRANSACTION_PROCESSING_TIME.start_timer(); let (transaction_str, config) = parse_params!(request.params()?, String, RpcSendTransactionConfig); + let transaction_str: String = some_or_err!(transaction_str); let config = config.unwrap_or_default(); let encoding = config.encoding.unwrap_or(UiTransactionEncoding::Base58); @@ -33,16 +38,16 @@ impl HttpDispatcher { { return Err(TransactionError::AlreadyProcessed.into()); } - debug!("Received transaction: {signature}, ensuring accounts"); self.ensure_transaction_accounts(&transaction).await?; // Based on the preflight flag, either execute and await the result, // or schedule (fire-and-forget) for background processing. if config.skip_preflight { - trace!("Scheduling transaction: {signature}"); + TRANSACTION_SKIP_PREFLIGHT.inc(); self.transactions_scheduler.schedule(transaction).await?; + trace!("Scheduling transaction {signature}"); } else { - trace!("Executing transaction: {signature}"); + trace!("Executing transaction {signature}"); self.transactions_scheduler.execute(transaction).await?; } diff --git a/magicblock-aperture/src/requests/mod.rs b/magicblock-aperture/src/requests/mod.rs index 0a826bf8c..7528a74c3 100644 --- a/magicblock-aperture/src/requests/mod.rs +++ b/magicblock-aperture/src/requests/mod.rs @@ -88,6 +88,84 @@ pub(crate) enum JsonRpcWsMethod { SlotUnsubscribe, } +impl JsonRpcHttpMethod { + pub(crate) fn as_str(&self) -> &'static str { + match self { + JsonRpcHttpMethod::GetAccountInfo => "getAccountInfo", + JsonRpcHttpMethod::GetBalance => "getBalance", + JsonRpcHttpMethod::GetBlock => "getBlock", + JsonRpcHttpMethod::GetBlockCommitment => "getBlockCommitment", + JsonRpcHttpMethod::GetBlockHeight => "getBlockHeight", + JsonRpcHttpMethod::GetBlockTime => "getBlockTime", + JsonRpcHttpMethod::GetBlocks => "getBlocks", + JsonRpcHttpMethod::GetBlocksWithLimit => "getBlocksWithLimit", + JsonRpcHttpMethod::GetClusterNodes => "getClusterNodes", + JsonRpcHttpMethod::GetEpochInfo => "getEpochInfo", + JsonRpcHttpMethod::GetEpochSchedule => "getEpochSchedule", + JsonRpcHttpMethod::GetFeeForMessage => "getFeeForMessage", + JsonRpcHttpMethod::GetFirstAvailableBlock => { + "getFirstAvailableBlock" + } + JsonRpcHttpMethod::GetGenesisHash => "getGenesisHash", + JsonRpcHttpMethod::GetHealth => "getHealth", + JsonRpcHttpMethod::GetHighestSnapshotSlot => { + "getHighestSnapshotSlot" + } + JsonRpcHttpMethod::GetIdentity => "getIdentity", + JsonRpcHttpMethod::GetLargestAccounts => "getLargestAccounts", + JsonRpcHttpMethod::GetLatestBlockhash => "getLatestBlockhash", + JsonRpcHttpMethod::GetMultipleAccounts => "getMultipleAccounts", + JsonRpcHttpMethod::GetProgramAccounts => "getProgramAccounts", + JsonRpcHttpMethod::GetSignatureStatuses => "getSignatureStatuses", + JsonRpcHttpMethod::GetSignaturesForAddress => { + "getSignaturesForAddress" + } + JsonRpcHttpMethod::GetSlot => "getSlot", + JsonRpcHttpMethod::GetSlotLeader => "getSlotLeader", + JsonRpcHttpMethod::GetSlotLeaders => "getSlotLeaders", + JsonRpcHttpMethod::GetSupply => "getSupply", + JsonRpcHttpMethod::GetTokenAccountBalance => { + "getTokenAccountBalance" + } + JsonRpcHttpMethod::GetTokenAccountsByDelegate => { + "getTokenAccountsByDelegate" + } + JsonRpcHttpMethod::GetTokenAccountsByOwner => { + "getTokenAccountsByOwner" + } + JsonRpcHttpMethod::GetTokenLargestAccounts => { + "getTokenLargestAccounts" + } + JsonRpcHttpMethod::GetTokenSupply => "getTokenSupply", + JsonRpcHttpMethod::GetTransaction => "getTransaction", + JsonRpcHttpMethod::GetTransactionCount => "getTransactionCount", + JsonRpcHttpMethod::GetVersion => "getVersion", + JsonRpcHttpMethod::IsBlockhashValid => "isBlockhashValid", + JsonRpcHttpMethod::MinimumLedgerSlot => "minimumLedgerSlot", + JsonRpcHttpMethod::RequestAirdrop => "requestAirdrop", + JsonRpcHttpMethod::SendTransaction => "sendTransaction", + JsonRpcHttpMethod::SimulateTransaction => "simulateTransaction", + } + } +} + +impl JsonRpcWsMethod { + pub(crate) fn as_str(&self) -> &'static str { + match self { + JsonRpcWsMethod::AccountSubscribe => "accountSubscribe", + JsonRpcWsMethod::AccountUnsubscribe => "accountUnsubscribe", + JsonRpcWsMethod::LogsSubscribe => "logsSubscribe", + JsonRpcWsMethod::LogsUnsubscribe => "logsUnsubscribe", + JsonRpcWsMethod::ProgramSubscribe => "programSubscribe", + JsonRpcWsMethod::ProgramUnsubscribe => "programUnsubscribe", + JsonRpcWsMethod::SignatureSubscribe => "signatureSubscribe", + JsonRpcWsMethod::SignatureUnsubscribe => "signatureUnsubscribe", + JsonRpcWsMethod::SlotSubscribe => "slotSubscribe", + JsonRpcWsMethod::SlotUnsubscribe => "slotUnsubscribe", + } + } +} + /// A helper macro for easily parsing positional parameters from a JSON-RPC request. /// /// This macro simplifies the process of extracting and deserializing parameters diff --git a/magicblock-aperture/src/server/http/dispatch.rs b/magicblock-aperture/src/server/http/dispatch.rs index 462754466..9c37a7083 100644 --- a/magicblock-aperture/src/server/http/dispatch.rs +++ b/magicblock-aperture/src/server/http/dispatch.rs @@ -6,6 +6,9 @@ use magicblock_core::link::{ transactions::TransactionSchedulerHandle, DispatchEndpoints, }; use magicblock_ledger::Ledger; +use magicblock_metrics::metrics::{ + RPC_REQUESTS_COUNT, RPC_REQUEST_HANDLING_TIME, +}; use crate::{ requests::{ @@ -111,6 +114,11 @@ impl HttpDispatcher { async fn process(&self, request: &mut JsonHttpRequest) -> HandlerResult { // Route the request to the correct handler based on the method name. use crate::requests::JsonRpcHttpMethod::*; + let method = request.method.as_str(); + RPC_REQUESTS_COUNT.with_label_values(&[method]).inc(); + let _timer = RPC_REQUEST_HANDLING_TIME + .with_label_values(&[method]) + .start_timer(); match request.method { GetAccountInfo => self.get_account_info(request).await, GetBalance => self.get_balance(request).await, diff --git a/magicblock-aperture/src/server/websocket/dispatch.rs b/magicblock-aperture/src/server/websocket/dispatch.rs index 37d56f30a..cac407de7 100644 --- a/magicblock-aperture/src/server/websocket/dispatch.rs +++ b/magicblock-aperture/src/server/websocket/dispatch.rs @@ -2,6 +2,7 @@ use std::collections::HashMap; use hyper::body::Bytes; use json::{Serialize, Value}; +use magicblock_metrics::metrics::RPC_REQUESTS_COUNT; use tokio::sync::mpsc; use super::connection::ConnectionID; @@ -65,6 +66,9 @@ impl WsDispatcher { request: &mut JsonWsRequest, ) -> RpcResult { use JsonRpcWsMethod::*; + RPC_REQUESTS_COUNT + .with_label_values(&[request.method.as_str()]) + .inc(); let result = match request.method { AccountSubscribe => self.account_subscribe(request).await, ProgramSubscribe => self.program_subscribe(request).await, diff --git a/magicblock-aperture/src/state/subscriptions.rs b/magicblock-aperture/src/state/subscriptions.rs index bb30e6241..4fb94c530 100644 --- a/magicblock-aperture/src/state/subscriptions.rs +++ b/magicblock-aperture/src/state/subscriptions.rs @@ -15,6 +15,7 @@ use magicblock_core::{ }, Slot, }; +use magicblock_metrics::metrics::RPC_WS_SUBSCRIPTIONS_COUNT; use parking_lot::RwLock; use solana_account::ReadableAccount; use solana_pubkey::Pubkey; @@ -105,7 +106,7 @@ impl SubscriptionsDb { .await .or_insert_with(|| UpdateSubscribers(vec![])) .add_subscriber(chan, encoder.clone()); - + let metric = SubMetricGuard::new("account-subscribe"); // Create a cleanup future that will be executed when the handle is dropped. let accounts = self.accounts.clone(); let callback = async move { @@ -116,6 +117,7 @@ impl SubscriptionsDb { if entry.remove_subscriber(conid, &encoder) { let _ = entry.remove(); } + drop(metric) }; let cleanup = CleanUp(Some(Box::pin(callback))); SubscriptionHandle { id, cleanup } @@ -146,6 +148,7 @@ impl SubscriptionsDb { .add_subscriber(chan, encoder.clone()); let programs = self.programs.clone(); + let metric = SubMetricGuard::new("program-subscribe"); let callback = async move { let Some(mut entry) = programs.get_async(&pubkey).await else { return; @@ -153,6 +156,7 @@ impl SubscriptionsDb { if entry.remove_subscriber(conid, &encoder) { let _ = entry.remove(); } + drop(metric) }; let cleanup = CleanUp(Some(Box::pin(callback))); SubscriptionHandle { id, cleanup } @@ -212,8 +216,10 @@ impl SubscriptionsDb { let id = self.logs.write().add_subscriber(chan, encoder.clone()); let logs = self.logs.clone(); + let metric = SubMetricGuard::new("logs-subscribe"); let callback = async move { logs.write().remove_subscriber(conid, &encoder); + drop(metric) }; let cleanup = CleanUp(Some(Box::pin(callback))); SubscriptionHandle { id, cleanup } @@ -239,8 +245,10 @@ impl SubscriptionsDb { let id = subscriber.id; let slot = self.slot.clone(); + let metric = SubMetricGuard::new("slot-subscribe"); let callback = async move { slot.write().txs.remove(&conid); + drop(metric) }; let cleanup = CleanUp(Some(Box::pin(callback))); SubscriptionHandle { id, cleanup } @@ -391,3 +399,20 @@ impl Drop for UpdateSubscriber { self.live.store(false, Ordering::Relaxed); } } + +pub(crate) struct SubMetricGuard(&'static str); + +impl SubMetricGuard { + pub(crate) fn new(name: &'static str) -> Self { + RPC_WS_SUBSCRIPTIONS_COUNT.with_label_values(&[name]).inc(); + Self(name) + } +} + +impl Drop for SubMetricGuard { + fn drop(&mut self) { + RPC_WS_SUBSCRIPTIONS_COUNT + .with_label_values(&[self.0]) + .dec(); + } +} diff --git a/magicblock-metrics/src/metrics/mod.rs b/magicblock-metrics/src/metrics/mod.rs index b0d807863..63788ca51 100644 --- a/magicblock-metrics/src/metrics/mod.rs +++ b/magicblock-metrics/src/metrics/mod.rs @@ -2,8 +2,8 @@ use std::sync::Once; pub use prometheus::HistogramTimer; use prometheus::{ - Histogram, HistogramOpts, IntCounter, IntCounterVec, IntGauge, IntGaugeVec, - Opts, Registry, + Histogram, HistogramOpts, HistogramVec, IntCounter, IntCounterVec, + IntGauge, IntGaugeVec, Opts, Registry, }; pub use types::{AccountClone, AccountCommit, Outcome}; mod types; @@ -27,8 +27,6 @@ const MILLIS_10_90: [f64; 9] = [0.01, 0.02, 0.03, 0.04, 0.05, 0.06, 0.07, 0.08, 0.09]; const MILLIS_100_900: [f64; 9] = [0.1, 0.2, 0.3, 0.4, 0.5, 0.6, 0.7, 0.8, 0.9]; const SECONDS_1_9: [f64; 9] = [1.0, 2.0, 3.0, 4.0, 5.0, 6.0, 7.0, 8.0, 9.0]; -const SECONDS_10_19: [f64; 10] = - [10.0, 11.0, 12.0, 13.0, 14.0, 15.0, 16.0, 17.0, 18.0, 19.0]; lazy_static::lazy_static! { pub (crate) static ref REGISTRY: Registry = Registry::new_custom(Some("mbv".to_string()), None).unwrap(); @@ -37,43 +35,6 @@ lazy_static::lazy_static! { "slot_count", "Slot Count", ).unwrap(); - static ref TRANSACTION_VEC_COUNT: IntCounterVec = IntCounterVec::new( - Opts::new("transaction_count", "Transaction Count"), - &["outcome"], - ).unwrap(); - - static ref FEE_PAYER_VEC_COUNT: IntCounterVec = IntCounterVec::new( - Opts::new("fee_payer_count", "Count of transactions signed by specific fee payers"), - &["fee_payer", "outcome"], - ).unwrap(); - - static ref EXECUTED_UNITS_COUNT: IntCounter = IntCounter::new( - "executed_units_count", "Executed Units (CU) Count", - ).unwrap(); - - static ref FEE_COUNT: IntCounter = IntCounter::new( - "fee_count", "Fee Count", - ).unwrap(); - - static ref ACCOUNT_CLONE_VEC_COUNT: IntCounterVec = IntCounterVec::new( - Opts::new("account_clone_count", "Count clones performed for specific accounts"), - &["kind", "pubkey", "owner"], - ).unwrap(); - - static ref ACCOUNT_COMMIT_VEC_COUNT: IntCounterVec = IntCounterVec::new( - Opts::new("account_commit_count", "Count commits performed for specific accounts"), - &["kind", "pubkey", "outcome"], - ).unwrap(); - - static ref ACCOUNT_COMMIT_TIME_HISTOGRAM: Histogram = Histogram::with_opts( - HistogramOpts::new("account_commit_time", "Time until each account commit transaction is confirmed on chain") - .buckets( - MILLIS_10_90.iter().chain( - MILLIS_100_900.iter()).chain( - SECONDS_1_9.iter()).chain( - SECONDS_10_19.iter()).cloned().collect() - ), - ).unwrap(); static ref CACHED_CLONE_OUTPUTS_COUNT: IntGauge = IntGauge::new( "magicblock_account_cloner_cached_outputs", @@ -132,71 +93,84 @@ lazy_static::lazy_static! { "accounts_count", "Number of accounts currently in the database", ).unwrap(); - static ref INMEM_ACCOUNTS_SIZE_GAUGE: IntGauge = IntGauge::new( - "inmemory_accounts_size", "Size of account states kept in RAM", - ).unwrap(); static ref PENDING_ACCOUNT_CLONES_GAUGE: IntGauge = IntGauge::new( "pending_account_clones", "Total number of account clone requests still in memory", ).unwrap(); - static ref ACTIVE_DATA_MODS_GAUGE: IntGauge = IntGauge::new( - "active_data_mods", "Total number of account data modifications held in memory", + static ref MONITORED_ACCOUNTS_GAUGE: IntGauge = IntGauge::new( + "monitored_accounts", "number of undelegated accounts, being monitored via websocket", ).unwrap(); - static ref ACTIVE_DATA_MODS_SIZE_GAUGE: IntGauge = IntGauge::new( - "active_data_mods_size", "Total memory consumption by account data modifications", + static ref SUBSCRIPTIONS_COUNT_GAUGE: IntGaugeVec = IntGaugeVec::new( + Opts::new("subscriptions_count", "number of active account subscriptions"), + &["shard"], ).unwrap(); - static ref SIGVERIFY_TIME_HISTOGRAM: Histogram = Histogram::with_opts( - HistogramOpts::new("sigverify_time", "Time spent in sigverify") - .buckets( - MICROS_10_90.iter().chain( - MICROS_100_900.iter()).chain( - MILLIS_1_9.iter()).cloned().collect() - ), + static ref EVICTED_ACCOUNTS_COUNT: IntGauge = IntGauge::new( + "evicted_accounts", "number of accounts forcefully removed from monitored list and database", ).unwrap(); - static ref ENSURE_ACCOUNTS_TIME_HISTOGRAM: Histogram = Histogram::with_opts( - HistogramOpts::new("ensure_accounts_time", "Time spent in ensure_accounts") + // ----------------- + // RPC/Aperture + // ----------------- + pub static ref ENSURE_ACCOUNTS_TIME: HistogramVec = HistogramVec::new( + HistogramOpts::new("ensure_accounts_time", "Time spent in ensuring account presence") .buckets( - MILLIS_1_9.iter().chain( + MICROS_10_90.iter().chain( + MICROS_100_900.iter()).chain( + MILLIS_1_9.iter()).chain( MILLIS_10_90.iter()).chain( MILLIS_100_900.iter()).chain( SECONDS_1_9.iter()).cloned().collect() ), + &["kind"] ).unwrap(); - static ref TRANSACTION_EXECUTION_TIME_HISTORY: Histogram = Histogram::with_opts( - HistogramOpts::new("transaction_execution_time", "Time spent in transaction execution") + pub static ref TRANSACTION_PROCESSING_TIME: Histogram = Histogram::with_opts( + HistogramOpts::new("transaction_processing_time", "Total time spent in transaction processing") .buckets( MICROS_10_90.iter().chain( MICROS_100_900.iter()).chain( - MILLIS_1_9.iter()).cloned().collect() + MILLIS_1_9.iter()).chain( + MILLIS_10_90.iter()).chain( + MILLIS_100_900.iter()).chain( + SECONDS_1_9.iter()).cloned().collect() ), ).unwrap(); - static ref FLUSH_ACCOUNTS_TIME_HISTOGRAM: Histogram = Histogram::with_opts( - HistogramOpts::new("flush_accounts_time", "Time spent flushing accounts to disk") + pub static ref RPC_REQUEST_HANDLING_TIME: HistogramVec = HistogramVec::new( + HistogramOpts::new("rpc_request_handling_time", "Time spent in rpc request handling") .buckets( - MILLIS_1_9.iter().chain( + MICROS_10_90.iter().chain( + MICROS_100_900.iter()).chain( + MILLIS_1_9.iter()).chain( MILLIS_10_90.iter()).chain( MILLIS_100_900.iter()).chain( SECONDS_1_9.iter()).cloned().collect() - ), + ), &["name"] ).unwrap(); - static ref MONITORED_ACCOUNTS_GAUGE: IntGauge = IntGauge::new( - "monitored_accounts", "number of undelegated accounts, being monitored via websocket", + pub static ref TRANSACTION_SKIP_PREFLIGHT: IntCounter = IntCounter::new( + "transaction_skip_preflight", "Count of transactions that skipped the preflight check", ).unwrap(); - static ref SUBSCRIPTIONS_COUNT_GAUGE: IntGaugeVec = IntGaugeVec::new( - Opts::new("subscriptions_count", "number of active account subscriptions"), - &["shard"], + pub static ref RPC_REQUESTS_COUNT: IntCounterVec = IntCounterVec::new( + Opts::new("rpc_requests_count", "Count of different rpc requests"), + &["name"], ).unwrap(); - static ref EVICTED_ACCOUNTS_COUNT: IntGauge = IntGauge::new( - "evicted_accounts", "number of accounts forcefully removed from monitored list and database", + pub static ref RPC_WS_SUBSCRIPTIONS_COUNT: IntGaugeVec = IntGaugeVec::new( + Opts::new("rpc_ws_subscriptions_count", "Count of active rpc websocket subscriptions"), + &["name"], + ).unwrap(); + + + // ----------------- + // Transaction Execution + // ----------------- + pub static ref FAILED_TRANSACTIONS_COUNT: IntCounter = IntCounter::new( + "failed_transactions_count", "Total number of failed transactions" ).unwrap(); @@ -227,13 +201,6 @@ pub(crate) fn register() { }; } register!(SLOT_COUNT); - register!(TRANSACTION_VEC_COUNT); - register!(FEE_PAYER_VEC_COUNT); - register!(EXECUTED_UNITS_COUNT); - register!(FEE_COUNT); - register!(ACCOUNT_CLONE_VEC_COUNT); - register!(ACCOUNT_COMMIT_VEC_COUNT); - register!(ACCOUNT_COMMIT_TIME_HISTOGRAM); register!(CACHED_CLONE_OUTPUTS_COUNT); register!(LEDGER_SIZE_GAUGE); register!(LEDGER_BLOCK_TIMES_GAUGE); @@ -249,20 +216,20 @@ pub(crate) fn register() { register!(LEDGER_ACCOUNT_MOD_DATA_GAUGE); register!(ACCOUNTS_SIZE_GAUGE); register!(ACCOUNTS_COUNT_GAUGE); - register!(INMEM_ACCOUNTS_SIZE_GAUGE); register!(PENDING_ACCOUNT_CLONES_GAUGE); - register!(ACTIVE_DATA_MODS_GAUGE); - register!(ACTIVE_DATA_MODS_SIZE_GAUGE); - register!(SIGVERIFY_TIME_HISTOGRAM); - register!(ENSURE_ACCOUNTS_TIME_HISTOGRAM); - register!(TRANSACTION_EXECUTION_TIME_HISTORY); - register!(FLUSH_ACCOUNTS_TIME_HISTOGRAM); register!(MONITORED_ACCOUNTS_GAUGE); register!(SUBSCRIPTIONS_COUNT_GAUGE); register!(EVICTED_ACCOUNTS_COUNT); register!(COMMITTOR_INTENTS_BACKLOG_COUNT); register!(COMMITTOR_FAILED_INTENTS_COUNT); register!(COMMITTOR_EXECUTORS_BUSY_COUNT); + register!(ENSURE_ACCOUNTS_TIME); + register!(RPC_REQUEST_HANDLING_TIME); + register!(TRANSACTION_PROCESSING_TIME); + register!(TRANSACTION_SKIP_PREFLIGHT); + register!(RPC_REQUESTS_COUNT); + register!(RPC_WS_SUBSCRIPTIONS_COUNT); + register!(FAILED_TRANSACTIONS_COUNT); }); } @@ -270,87 +237,10 @@ pub fn inc_slot() { SLOT_COUNT.inc(); } -pub fn inc_transaction(is_ok: bool, fee_payer: &str) { - let outcome = if is_ok { "success" } else { "error" }; - TRANSACTION_VEC_COUNT.with_label_values(&[outcome]).inc(); - FEE_PAYER_VEC_COUNT - .with_label_values(&[fee_payer, outcome]) - .inc(); -} - -pub fn inc_executed_units(executed_units: u64) { - EXECUTED_UNITS_COUNT.inc_by(executed_units); -} - -pub fn inc_fee(fee: u64) { - FEE_COUNT.inc_by(fee); -} - -pub fn inc_account_clone(account_clone: AccountClone) { - use AccountClone::*; - match account_clone { - FeePayer { - pubkey, - balance_pda, - } => { - ACCOUNT_CLONE_VEC_COUNT - .with_label_values(&[ - "feepayer", - pubkey, - balance_pda.unwrap_or(""), - ]) - .inc(); - } - Undelegated { pubkey, owner } => { - ACCOUNT_CLONE_VEC_COUNT - .with_label_values(&["undelegated", pubkey, owner]) - .inc(); - } - Delegated { pubkey, owner } => { - ACCOUNT_CLONE_VEC_COUNT - .with_label_values(&["delegated", pubkey, owner]) - .inc(); - } - Program { pubkey } => { - ACCOUNT_CLONE_VEC_COUNT - .with_label_values(&["program", pubkey, ""]) - .inc(); - } - } -} - -pub fn inc_account_commit(account_commit: AccountCommit) { - use AccountCommit::*; - match account_commit { - CommitOnly { pubkey, outcome } => { - ACCOUNT_COMMIT_VEC_COUNT - .with_label_values(&["commit", pubkey, outcome.as_str()]) - .inc(); - } - CommitAndUndelegate { pubkey, outcome } => { - ACCOUNT_COMMIT_VEC_COUNT - .with_label_values(&[ - "commit_and_undelegate", - pubkey, - outcome.as_str(), - ]) - .inc(); - } - } -} - -pub fn account_commit_start() -> HistogramTimer { - ACCOUNT_COMMIT_TIME_HISTOGRAM.start_timer() -} - pub fn set_cached_clone_outputs_count(count: usize) { CACHED_CLONE_OUTPUTS_COUNT.set(count as i64); } -pub fn account_commit_end(timer: HistogramTimer) { - timer.stop_and_record(); -} - pub fn set_subscriptions_count(count: usize, shard: &str) { SUBSCRIPTIONS_COUNT_GAUGE .with_label_values(&[shard]) @@ -405,18 +295,6 @@ pub fn set_ledger_account_mod_data_count(count: i64) { LEDGER_ACCOUNT_MOD_DATA_GAUGE.set(count); } -pub fn set_accounts_size(size: u64) { - ACCOUNTS_SIZE_GAUGE.set(size as i64); -} - -pub fn set_accounts_count(count: usize) { - ACCOUNTS_COUNT_GAUGE.set(count as i64); -} - -pub fn adjust_inmemory_accounts_size(delta: i64) { - INMEM_ACCOUNTS_SIZE_GAUGE.add(delta); -} - pub fn inc_pending_clone_requests() { PENDING_ACCOUNT_CLONES_GAUGE.inc() } @@ -425,36 +303,10 @@ pub fn dec_pending_clone_requests() { PENDING_ACCOUNT_CLONES_GAUGE.dec() } -pub fn adjust_active_data_mods(delta: i64) { - ACTIVE_DATA_MODS_GAUGE.add(delta) -} - -pub fn adjust_active_data_mods_size(delta: i64) { - ACTIVE_DATA_MODS_SIZE_GAUGE.add(delta); -} - -pub fn observe_sigverify_time(f: F) -> T -where - F: FnOnce() -> T, -{ - SIGVERIFY_TIME_HISTOGRAM.observe_closure_duration(f) -} - -pub fn ensure_accounts_start() -> HistogramTimer { - ENSURE_ACCOUNTS_TIME_HISTOGRAM.start_timer() -} - pub fn ensure_accounts_end(timer: HistogramTimer) { timer.stop_and_record(); } -pub fn observe_transaction_execution_time(f: F) -> T -where - F: FnOnce() -> T, -{ - TRANSACTION_EXECUTION_TIME_HISTORY.observe_closure_duration(f) -} - pub fn adjust_monitored_accounts_count(count: usize) { MONITORED_ACCOUNTS_GAUGE.set(count as i64); } @@ -473,10 +325,3 @@ pub fn inc_committor_failed_intents_count() { pub fn set_committor_executors_busy_count(value: i64) { COMMITTOR_EXECUTORS_BUSY_COUNT.set(value) } - -pub fn observe_flush_accounts_time(f: F) -> T -where - F: FnOnce() -> T, -{ - FLUSH_ACCOUNTS_TIME_HISTOGRAM.observe_closure_duration(f) -} diff --git a/magicblock-processor/Cargo.toml b/magicblock-processor/Cargo.toml index 490720242..8aa007057 100644 --- a/magicblock-processor/Cargo.toml +++ b/magicblock-processor/Cargo.toml @@ -16,6 +16,7 @@ tokio = { workspace = true } magicblock-accounts-db = { workspace = true } magicblock-core = { workspace = true } magicblock-ledger = { workspace = true } +magicblock-metrics = { workspace = true } magicblock-program = { workspace = true } solana-account = { workspace = true } diff --git a/magicblock-processor/src/executor/processing.rs b/magicblock-processor/src/executor/processing.rs index 42f2d417b..9a085aa63 100644 --- a/magicblock-processor/src/executor/processing.rs +++ b/magicblock-processor/src/executor/processing.rs @@ -8,6 +8,7 @@ use magicblock_core::link::{ TransactionStatus, TxnExecutionResultTx, TxnSimulationResultTx, }, }; +use magicblock_metrics::metrics::FAILED_TRANSACTIONS_COUNT; use solana_pubkey::Pubkey; use solana_svm::{ account_loader::{AccountsBalances, CheckedTransactionDetails}, @@ -54,6 +55,7 @@ impl super::TransactionExecutor { if let Err(err) = result { let status = Err(err); self.commit_failed_transaction(txn, status.clone()); + FAILED_TRANSACTIONS_COUNT.inc(); tx.map(|tx| tx.send(status)); return; } diff --git a/programs/magicblock/src/mutate_accounts/account_mod_data.rs b/programs/magicblock/src/mutate_accounts/account_mod_data.rs index 484a86015..d313b0202 100644 --- a/programs/magicblock/src/mutate_accounts/account_mod_data.rs +++ b/programs/magicblock/src/mutate_accounts/account_mod_data.rs @@ -1,6 +1,5 @@ use std::{ collections::HashMap, - ops::Neg, sync::{ atomic::{AtomicU64, Ordering}, Arc, Mutex, RwLock, @@ -69,22 +68,11 @@ pub(crate) fn set_account_mod_data(data: Vec) -> u64 { .lock() .expect("DATA_MODS poisoned") .insert(id, data); - // update metrics related to total count of data mods - magicblock_metrics::metrics::adjust_active_data_mods(1); id } pub(super) fn get_data(id: u64) -> Option> { - DATA_MODS - .lock() - .expect("DATA_MODS poisoned") - .remove(&id) - .inspect(|v| { - // decrement metrics - let len = (v.len() as i64).neg(); - magicblock_metrics::metrics::adjust_active_data_mods_size(len); - magicblock_metrics::metrics::adjust_active_data_mods(-1); - }) + DATA_MODS.lock().expect("DATA_MODS poisoned").remove(&id) } pub fn init_persister(persister: Arc) {