diff --git a/Cargo.toml b/Cargo.toml index e066268..4ff92de 100644 --- a/Cargo.toml +++ b/Cargo.toml @@ -19,7 +19,8 @@ toml = "0.8" # CLI & Logging clap = { version = "4.0", features = ["derive"] } tracing = "0.1" -tracing-subscriber = "0.3" +tracing-subscriber = { version = "0.3", features = ["env-filter"] } +tracing-appender = "0.2" comfy-table = "7.1" indicatif = "0.17" diff --git a/src/actors/monitor/txn_tracker.rs b/src/actors/monitor/txn_tracker.rs index 4faf2be..800fc00 100644 --- a/src/actors/monitor/txn_tracker.rs +++ b/src/actors/monitor/txn_tracker.rs @@ -5,7 +5,7 @@ use std::time::{Duration, Instant}; use alloy::consensus::Account; use alloy::primitives::TxHash; -use comfy_table::{presets::UTF8_FULL, Attribute, Cell, Color, Table}; +use comfy_table::{presets::UTF8_FULL, Cell, Table}; use tracing::{debug, error, warn}; use crate::actors::monitor::SubmissionResult; @@ -615,22 +615,6 @@ impl TxnTracker { ) }; - let mut plan_summaries = Vec::new(); - - if !self.plan_trackers.is_empty() { - for (_plan_id, tracker) in &self.plan_trackers { - plan_summaries.push(format!( - "{}: {}/{}", - tracker.plan_name, tracker.resolved_transactions, tracker.produce_transactions - )); - } - } else if let Some((_plan_id, tracker)) = &self.last_completed_plan { - plan_summaries.push(format!( - "{}: {}/{} done", - tracker.plan_name, tracker.resolved_transactions, tracker.produce_transactions - )); - } - // Calculate success rate let success_rate = if self.total_produced_transactions > 0 { self.total_resolved_transactions as f64 / self.total_produced_transactions as f64 @@ -639,177 +623,114 @@ impl TxnTracker { 0.0 }; - let mut table = Table::new(); - table.load_preset(UTF8_FULL); - - // Set table header - table.set_header(vec![ - "Plan Name", - "Progress", - "Success%", - "SendFail", - "ExecFail", - "Status", - ]); - - // Add individual plan rows - if !self.plan_trackers.is_empty() { - for (_plan_id, tracker) in &self.plan_trackers { - let plan_success_rate = if tracker.resolved_transactions > 0 { - let successful = tracker - .resolved_transactions - .saturating_sub(tracker.failed_submissions + tracker.failed_executions); - successful as f64 / tracker.resolved_transactions as f64 * 100.0 - } else if tracker.produce_transactions > 0 { - // If no transactions resolved yet, can't calculate success rate - 0.0 - } else { - 100.0 - }; - - let progress_color = - if tracker.resolved_transactions as usize >= tracker.produce_transactions { - Color::Green - } else { - Color::Yellow - }; + // Count plan states + let mut produced_plans = 0u64; + let mut not_produced_plans = 0u64; + let mut completed_plans = 0u64; + let mut in_progress_plans = 0u64; + let mut timed_out_txns = 0u64; - let status = if tracker.plan_produced - && tracker.resolved_transactions as usize >= tracker.produce_transactions - { - if tracker.failed_submissions + tracker.failed_executions > 0 { - "Completed (w/ Errors)" - } else { - "Completed" - } + for (_plan_id, tracker) in &self.plan_trackers { + if tracker.plan_produced { + produced_plans += 1; + if tracker.resolved_transactions as usize >= tracker.produce_transactions { + completed_plans += 1; } else { - "In Progress" - }; + in_progress_plans += 1; + } + } else { + not_produced_plans += 1; + } + } - table.add_row(vec![ - Cell::new(&tracker.plan_name).fg(Color::Cyan), - Cell::new(&format!( - "{}/{}", - format_large_number(tracker.resolved_transactions), - format_large_number(tracker.produce_transactions as u64) - )) - .fg(progress_color), - Cell::new(&format!("{:.1}", plan_success_rate)).fg( - if plan_success_rate >= 95.0 { - Color::Green - } else if plan_success_rate >= 80.0 { - Color::Yellow - } else { - Color::Red - }, - ), - Cell::new(&format_large_number(tracker.failed_submissions)).fg( - if tracker.failed_submissions > 0 { - Color::Red - } else { - Color::Green - }, - ), - Cell::new(&format_large_number(tracker.failed_executions)).fg( - if tracker.failed_executions > 0 { - Color::Red - } else { - Color::Green - }, - ), - Cell::new(status).fg(if status.contains("Completed") { - Color::Green - } else { - Color::Yellow - }), - ]); + // Count timed out pending txns (those waiting > RETRY_TIMEOUT) + for pending_info in &self.pending_txns { + if pending_info.submit_time.elapsed() > RETRY_TIMEOUT { + timed_out_txns += 1; } - } else if let Some((_plan_id, tracker)) = &self.last_completed_plan { - let plan_success_rate = if tracker.resolved_transactions > 0 { - let successful = tracker - .resolved_transactions - .saturating_sub(tracker.failed_submissions + tracker.failed_executions); - successful as f64 / tracker.resolved_transactions as f64 * 100.0 - } else { - 100.0 - }; - - table.add_row(vec![ - Cell::new(&format!("{} (Last)", tracker.plan_name)).fg(Color::DarkGrey), - Cell::new(&format!( - "{}/{}", - format_large_number(tracker.resolved_transactions), - format_large_number(tracker.produce_transactions as u64) - )) - .fg(Color::Green), - Cell::new(&format!("{:.1}", plan_success_rate)).fg(Color::Green), - Cell::new(&format_large_number(tracker.failed_submissions)).fg( - if tracker.failed_submissions > 0 { - Color::Red - } else { - Color::Green - }, - ), - Cell::new(&format_large_number(tracker.failed_executions)).fg( - if tracker.failed_executions > 0 { - Color::Red - } else { - Color::Green - }, - ), - Cell::new("Done").fg(Color::Green), - ]); } - // Add summary row + let pending_txns = self.pending_txns.len() as u64; + + let mut table = Table::new(); + table.load_preset(UTF8_FULL); + + // Set table header - summary statistics + table.set_header(vec![ + "Metric", + "Value", + "Metric", + "Value", + ]); + + // Row 1: Txn progress and TPS table.add_row(vec![ - Cell::new("TOTAL") - .add_attribute(Attribute::Bold) - .fg(Color::Blue), + Cell::new("Progress"), Cell::new(&format!( "{}/{}", format_large_number(self.total_resolved_transactions), format_large_number(self.total_produced_transactions) - )) - .add_attribute(Attribute::Bold) - .fg(Color::Blue), - Cell::new(&format!("{:.1}", success_rate)) - .add_attribute(Attribute::Bold) - .fg(Color::Blue), - Cell::new(&format_large_number(self.total_failed_submissions)) - .add_attribute(Attribute::Bold) - .fg(Color::Blue), - Cell::new(&format_large_number(self.total_failed_executions)) - .add_attribute(Attribute::Bold) - .fg(Color::Blue), - Cell::new(&format!( - "TPS:{:.1} | Lat: {:.1}s | Pool:{}/{}", - tps, - avg_latency.as_secs_f64(), - format_large_number(self.mempool_pending), - format_large_number(self.mempool_queued) - )) - .add_attribute(Attribute::Bold) - .fg(Color::Magenta), + )), + Cell::new("TPS"), + Cell::new(&format!("{:.1}", tps)), ]); + // Row 2: Pending txns and latency table.add_row(vec![ - Cell::new("SYSTEM") - .add_attribute(Attribute::Bold) - .fg(Color::Yellow), - Cell::new(""), // Progress placeholder - Cell::new(""), // Success% placeholder - Cell::new(""), // SendFail placeholder - Cell::new(""), // ExecFail placeholder - Cell::new(&format!( - "Ready Accounts: {} | Processing: {}", - format_large_number(self.producer_ready_accounts), - format_large_number(self.producer_sending_txns) - )) - .add_attribute(Attribute::Bold) - .fg(Color::Yellow), + Cell::new("Pending Txns"), + Cell::new(&format_large_number(pending_txns)), + Cell::new("Avg Latency"), + Cell::new(&format!("{:.1}s", avg_latency.as_secs_f64())), + ]); + + // Row 3: Timed out txns and success rate + table.add_row(vec![ + Cell::new("Timed Out Txns"), + Cell::new(&format_large_number(timed_out_txns)), + Cell::new("Success%"), + Cell::new(&format!("{:.1}%", success_rate)), + ]); + + // Row 4: Produced plans and not produced plans + table.add_row(vec![ + Cell::new("Produced Plans"), + Cell::new(&format_large_number(produced_plans)), + Cell::new("Not Produced"), + Cell::new(&format_large_number(not_produced_plans)), + ]); + + // Row 5: Completed plans and in progress plans + table.add_row(vec![ + Cell::new("Completed Plans"), + Cell::new(&format_large_number(completed_plans)), + Cell::new("In Progress"), + Cell::new(&format_large_number(in_progress_plans)), + ]); + + // Row 6: Send failures and execution failures + table.add_row(vec![ + Cell::new("Send Failures"), + Cell::new(&format_large_number(self.total_failed_submissions)), + Cell::new("Exec Failures"), + Cell::new(&format_large_number(self.total_failed_executions)), + ]); + + // Row 7: Mempool stats + table.add_row(vec![ + Cell::new("Pool Pending"), + Cell::new(&format_large_number(self.mempool_pending)), + Cell::new("Pool Queued"), + Cell::new(&format_large_number(self.mempool_queued)), + ]); + + // Row 8: Producer stats + table.add_row(vec![ + Cell::new("Ready Accounts"), + Cell::new(&format_large_number(self.producer_ready_accounts)), + Cell::new("Processing"), + Cell::new(&format_large_number(self.producer_sending_txns)), ]); - println!("{}", table); + tracing::info!("\n{}", table); } } diff --git a/src/config/bench_config.rs b/src/config/bench_config.rs index 270a5f4..65d5f99 100644 --- a/src/config/bench_config.rs +++ b/src/config/bench_config.rs @@ -25,6 +25,12 @@ pub struct BenchConfig { pub enable_swap_token: bool, #[serde(default)] pub address_pool_type: AddressPoolType, + #[serde(default = "default_log_path")] + pub log_path: String, +} + +fn default_log_path() -> String { + "./log.log".to_string() } /// Node and chain configuration diff --git a/src/eth/eth_cli.rs b/src/eth/eth_cli.rs index cb96c5d..8fa681c 100644 --- a/src/eth/eth_cli.rs +++ b/src/eth/eth_cli.rs @@ -7,14 +7,14 @@ use alloy::{ rpc::types::TransactionReceipt, }; use anyhow::{Context as AnyhowContext, Result}; -use comfy_table::{presets::UTF8_FULL, Attribute, Cell, Color, Table}; +use comfy_table::{presets::UTF8_FULL, Cell, Table}; use rand::Rng; use serde::{Deserialize, Deserializer, Serialize}; use std::collections::HashMap; use std::sync::Arc; use std::time::Instant; use tokio::time::{sleep, Duration}; -use tracing::{debug, warn}; +use tracing::{debug, info, warn}; use url::Url; /// Format large numbers with appropriate suffixes (K, M, B) @@ -336,7 +336,7 @@ impl EthHttpCli { pub async fn log_metrics_summary(&self) { let metrics = self.get_metrics().await; if metrics.per_method.is_empty() { - println!("RPC Metrics for [{}]: No requests recorded yet.", self.rpc); + info!("RPC Metrics for [{}]: No requests recorded yet.", self.rpc); return; } @@ -366,31 +366,13 @@ impl EthHttpCli { 0.0 }; - let color = if success_rate >= 95.0 { - Color::Green - } else if success_rate >= 80.0 { - Color::Yellow - } else { - Color::Red - }; - table.add_row(vec![ - Cell::new(method).fg(Color::Cyan), - Cell::new(&format_large_number(stats.requests_sent)).fg(Color::White), - Cell::new(&format_large_number(stats.requests_succeeded)).fg(Color::Green), - Cell::new(&format_large_number(stats.requests_failed)).fg( - if stats.requests_failed > 0 { - Color::Red - } else { - Color::Green - }, - ), - Cell::new(&format!("{:.1}%", success_rate)).fg(color), - Cell::new(&format!("{:.1}ms", avg_latency)).fg(if avg_latency > 100.0 { - Color::Yellow - } else { - Color::Green - }), + Cell::new(method), + Cell::new(&format_large_number(stats.requests_sent)), + Cell::new(&format_large_number(stats.requests_succeeded)), + Cell::new(&format_large_number(stats.requests_failed)), + Cell::new(&format!("{:.1}%", success_rate)), + Cell::new(&format!("{:.1}ms", avg_latency)), ]); } @@ -419,27 +401,15 @@ impl EthHttpCli { }; table.add_row(vec![ - Cell::new("TOTAL") - .add_attribute(Attribute::Bold) - .fg(Color::Blue), - Cell::new(&format_large_number(total_sent)) - .add_attribute(Attribute::Bold) - .fg(Color::Blue), - Cell::new(&format_large_number(total_succeeded)) - .add_attribute(Attribute::Bold) - .fg(Color::Blue), - Cell::new(&format_large_number(total_failed)) - .add_attribute(Attribute::Bold) - .fg(Color::Blue), - Cell::new(&format!("{:.1}%", overall_success_rate)) - .add_attribute(Attribute::Bold) - .fg(Color::Blue), - Cell::new(&format!("{:.1}ms", overall_avg_latency)) - .add_attribute(Attribute::Bold) - .fg(Color::Magenta), + Cell::new("TOTAL"), + Cell::new(&format_large_number(total_sent)), + Cell::new(&format_large_number(total_succeeded)), + Cell::new(&format_large_number(total_failed)), + Cell::new(&format!("{:.1}%", overall_success_rate)), + Cell::new(&format!("{:.1}ms", overall_avg_latency)), ]); - println!("{}", table); + info!("\n{}", table); } /// Reset metrics diff --git a/src/main.rs b/src/main.rs index 431342a..764f6b5 100644 --- a/src/main.rs +++ b/src/main.rs @@ -16,7 +16,9 @@ use std::{ time::{Duration, Instant}, }; use tokio::io::{AsyncBufReadExt, BufReader as TokioBufReader}; -use tracing::{error, info, Level}; +use tracing::{error, info}; + +use tracing_subscriber::{layer::SubscriberExt, util::SubscriberInitExt, EnvFilter}; use crate::{ actors::{consumer::Consumer, producer::Producer, Monitor, RegisterTxnPlan}, @@ -257,12 +259,50 @@ async fn start_bench() -> Result<()> { let args = Args::parse(); let benchmark_config = BenchConfig::load(&args.config).unwrap(); assert!(benchmark_config.accounts.num_accounts >= benchmark_config.target_tps as usize); - tracing_subscriber::fmt() - .with_max_level(Level::INFO) - .with_file(false) - .with_line_number(false) - .with_thread_ids(false) - .init(); + + // Initialize tracing + let log_path = benchmark_config.log_path.trim(); + let env_filter = EnvFilter::try_from_default_env() + .unwrap_or_else(|_| EnvFilter::new("info")); + + let _guard = if log_path.is_empty() || log_path.eq_ignore_ascii_case("console") { + // Console only + tracing_subscriber::fmt() + .with_env_filter(env_filter) + .with_file(false) + .with_line_number(false) + .with_thread_ids(false) + .init(); + None + } else { + // File logging + let path = std::path::Path::new(log_path); + let directory = path.parent().unwrap_or_else(|| std::path::Path::new(".")); + let file_stem = path.file_stem().unwrap_or_else(|| std::ffi::OsStr::new("gravity_bench")); + let extension = path.extension().unwrap_or_else(|| std::ffi::OsStr::new("log")); + + // Ensure directory exists + std::fs::create_dir_all(directory).unwrap(); + + let timestamp = chrono::Local::now().format("%Y-%m-%d-%H-%M-%S").to_string(); + let new_filename = format!("{}.{}.{}", file_stem.to_string_lossy(), timestamp, extension.to_string_lossy()); + let full_path = directory.join(new_filename); + + let file = std::fs::File::create(&full_path).unwrap(); + let (non_blocking, guard) = tracing_appender::non_blocking(file); + + tracing_subscriber::registry() + .with(env_filter) + .with( + tracing_subscriber::fmt::layer() + .with_writer(non_blocking) + .with_ansi(false) + ) + .init(); + + println!("Logging to file: {:?}", full_path); + Some(guard) + }; let contract_config = if args.recover { info!("Starting in recovery mode...");