diff --git a/.changelog/unreleased/features/ibc-relayer-cli/2852-add-debug-flag.md b/.changelog/unreleased/features/ibc-relayer-cli/2852-add-debug-flag.md new file mode 100644 index 0000000000..42d86fbc0d --- /dev/null +++ b/.changelog/unreleased/features/ibc-relayer-cli/2852-add-debug-flag.md @@ -0,0 +1,5 @@ +- Add a global flag `--debug` which can take one or more of the following values, separated by commas: + - `rpc`: show RPC debug logs + - `profiling`: show profiling information in the console + - `profiling-json`: dump the profiling information to a JSON file in the directory specified in `PROFILING_DIR` env variable if present, or the current directory otherwise. + ([#2852](https://github.com/informalsystems/hermes/issues/2852)) \ No newline at end of file diff --git a/crates/relayer-cli/Cargo.toml b/crates/relayer-cli/Cargo.toml index 2441cdf03b..bd030efacf 100644 --- a/crates/relayer-cli/Cargo.toml +++ b/crates/relayer-cli/Cargo.toml @@ -21,7 +21,6 @@ name = "hermes" default = ["telemetry", "rest-server", "std", "eyre_tracer",] std = ["flex-error/std"] eyre_tracer = ["flex-error/eyre_tracer"] -profiling = ["ibc-relayer/profiling"] telemetry = ["ibc-relayer/telemetry", "ibc-telemetry"] rest-server = ["ibc-relayer-rest"] diff --git a/crates/relayer-cli/src/application.rs b/crates/relayer-cli/src/application.rs index 56fe481633..b2bca10c0a 100644 --- a/crates/relayer-cli/src/application.rs +++ b/crates/relayer-cli/src/application.rs @@ -10,7 +10,7 @@ use abscissa_core::{ terminal::ColorChoice, Application, Configurable, FrameworkError, FrameworkErrorKind, StandardPaths, }; -use ibc_relayer::config::Config; +use ibc_relayer::{config::Config, util::debug_section::DebugSection}; use crate::{ components::{JsonTracing, PrettyTracing}, @@ -47,6 +47,9 @@ pub struct CliApp { /// Toggle json output on/off. Changed with the global config option `-j` / `--json`. json_output: bool, + /// Enable the given debug sections. + debug_sections: Vec, + /// Path to the config file. config_path: Option, } @@ -61,6 +64,7 @@ impl Default for CliApp { config: CfgCell::default(), state: application::State::default(), json_output: false, + debug_sections: Vec::default(), config_path: None, } } @@ -72,6 +76,16 @@ impl CliApp { self.json_output } + /// Returns the enabled debug sections + pub fn debug_sections(&self) -> &[DebugSection] { + &self.debug_sections + } + + /// Returns `true` if the given debug section is enabled + pub fn debug_enabled(&self, section: DebugSection) -> bool { + self.debug_sections.contains(§ion) + } + /// Returns the path to the configuration file pub fn config_path(&self) -> Option<&PathBuf> { self.config_path.as_ref() @@ -173,13 +187,21 @@ impl Application for CliApp { // Update the `json_output` flag used by `conclude::Output` self.json_output = command.json; + // Update the `debug_sections` flag + self.debug_sections = command.debug.iter().copied().map(Into::into).collect(); + + // Enable profiling if requested + let enable_console = self.debug_enabled(DebugSection::Profiling); + let enable_json = self.debug_enabled(DebugSection::ProfilingJson); + ibc_relayer::util::profiling::enable(enable_console, enable_json); + if command.json { // Enable JSON by using the crate-level `Tracing` - let tracing = JsonTracing::new(config.global)?; + let tracing = JsonTracing::new(config.global, &self.debug_sections)?; Ok(vec![Box::new(terminal), Box::new(tracing)]) } else { // Use abscissa's tracing, which pretty-prints to the terminal obeying log levels - let tracing = PrettyTracing::new(config.global)?; + let tracing = PrettyTracing::new(config.global, &self.debug_sections)?; Ok(vec![Box::new(terminal), Box::new(tracing)]) } } diff --git a/crates/relayer-cli/src/commands/start.rs b/crates/relayer-cli/src/commands/start.rs index 3d9d3a4dfd..e75685cd8c 100644 --- a/crates/relayer-cli/src/commands/start.rs +++ b/crates/relayer-cli/src/commands/start.rs @@ -1,4 +1,5 @@ use ibc_relayer::supervisor::SupervisorOptions; +use ibc_relayer::util::debug_section::DebugSection; use std::error::Error; use std::io; @@ -27,17 +28,20 @@ pub struct StartCmd { impl Runnable for StartCmd { fn run(&self) { - #[cfg(feature = "profiling")] - { + let app = app_reader(); + + if app.debug_enabled(DebugSection::ProfilingJson) { use chrono::prelude::*; use std::env; use std::path::Path; - let profile_dir = env::var("PROFILE_DIR").unwrap_or_else(|_| ".".to_string()); + use ibc_relayer::util::profiling::open_or_create_profile_file; + + let profile_dir = env::var("PROFILING_DIR").unwrap_or_else(|_| ".".to_string()); let now = Utc::now(); let path_str = format!( - "{}/hermes-{:04}-{:02}-{:02}-{:02}{:02}{:02}.prof", + "{}/hermes-{:04}-{:02}-{:02}-{:02}{:02}{:02}-prof.json", profile_dir, now.year(), now.month(), @@ -46,8 +50,8 @@ impl Runnable for StartCmd { now.minute(), now.second() ); - let file_name = Path::new(&path_str); - ibc_relayer::macros::profiling::open_or_create_profile_file(file_name); + + open_or_create_profile_file(Path::new(&path_str)); } let config = (*app_config()).clone(); diff --git a/crates/relayer-cli/src/components.rs b/crates/relayer-cli/src/components.rs index 84f5c36855..a89aa6e5a9 100644 --- a/crates/relayer-cli/src/components.rs +++ b/crates/relayer-cli/src/components.rs @@ -3,7 +3,10 @@ use abscissa_core::{Component, FrameworkError, FrameworkErrorKind}; use tracing_subscriber::{filter::EnvFilter, util::SubscriberInitExt, FmtSubscriber}; -use ibc_relayer::config::{GlobalConfig, LogLevel}; +use ibc_relayer::{ + config::{GlobalConfig, LogLevel}, + util::debug_section::DebugSection, +}; use crate::config::Error; @@ -22,8 +25,8 @@ pub struct JsonTracing; impl JsonTracing { /// Creates a new [`JsonTracing`] component - pub fn new(cfg: GlobalConfig) -> Result { - let filter = build_tracing_filter(cfg.log_level)?; + pub fn new(cfg: GlobalConfig, debug_sections: &[DebugSection]) -> Result { + let filter = build_tracing_filter(cfg.log_level, debug_sections)?; // Note: JSON formatter is un-affected by ANSI 'color' option. Set to 'false'. let use_color = false; @@ -55,8 +58,8 @@ pub struct PrettyTracing; impl PrettyTracing { /// Creates a new [`PrettyTracing`] component - pub fn new(cfg: GlobalConfig) -> Result { - let filter = build_tracing_filter(cfg.log_level)?; + pub fn new(cfg: GlobalConfig, debug_sections: &[DebugSection]) -> Result { + let filter = build_tracing_filter(cfg.log_level, debug_sections)?; // Construct a tracing subscriber with the supplied filter and enable reloading. let builder = FmtSubscriber::builder() @@ -98,10 +101,18 @@ fn default_directive(log_level: LogLevel) -> String { /// Builds a tracing filter based on the input `log_level`. /// Enables tracing exclusively for the relayer crates. /// Returns error if the filter failed to build. -fn build_tracing_filter(default_level: LogLevel) -> Result { - let directive = +fn build_tracing_filter( + default_level: LogLevel, + debug_sections: &[DebugSection], +) -> Result { + let mut directive = std::env::var(HERMES_LOG_VAR).unwrap_or_else(|_| default_directive(default_level)); + if debug_sections.contains(&DebugSection::Rpc) { + // Enable debug tracing for the `tendermint_rpc` crate as well + directive.push_str(",tendermint_rpc=debug"); + } + // Build the filter directive match EnvFilter::try_new(&directive) { Ok(out) => Ok(out), diff --git a/crates/relayer-cli/src/entry.rs b/crates/relayer-cli/src/entry.rs index 51fa5afd31..29fa21c0da 100644 --- a/crates/relayer-cli/src/entry.rs +++ b/crates/relayer-cli/src/entry.rs @@ -5,11 +5,29 @@ use std::process; use abscissa_core::clap::Parser; use abscissa_core::{Command, Configurable, FrameworkError, Runnable}; -use clap::IntoApp; +use clap::{IntoApp, ValueEnum}; use ibc_relayer::config::Config; +use ibc_relayer::util::debug_section::DebugSection; use crate::commands::CliCmd; +#[derive(Copy, Clone, Debug, ValueEnum)] +pub enum CliDebugSection { + Rpc, + Profiling, + ProfilingJson, +} + +impl From for DebugSection { + fn from(section: CliDebugSection) -> Self { + match section { + CliDebugSection::Rpc => DebugSection::Rpc, + CliDebugSection::Profiling => DebugSection::Profiling, + CliDebugSection::ProfilingJson => DebugSection::ProfilingJson, + } + } +} + /// Entry point for Hermes CLI. #[derive(Command, Debug, Parser)] #[clap(author, about, version)] @@ -22,6 +40,15 @@ pub struct EntryPoint { #[clap(long = "json", help = "Enable JSON output")] pub json: bool, + /// Enable the given debug sections, separated by commas. + #[clap( + long = "debug", + help = "Enable debug output for the given section(s), comma separated, can be repeated.", + value_enum, + value_delimiter = ',' + )] + pub debug: Vec, + /// Subcommand to execute. /// /// The `command` option will delegate option parsing to the command type, diff --git a/crates/relayer/Cargo.toml b/crates/relayer/Cargo.toml index f4644295dc..eb096d0c46 100644 --- a/crates/relayer/Cargo.toml +++ b/crates/relayer/Cargo.toml @@ -17,7 +17,6 @@ all-features = true [features] default = ["flex-error/std", "flex-error/eyre_tracer"] -profiling = [] telemetry = ["ibc-telemetry"] [dependencies] diff --git a/crates/relayer/src/lib.rs b/crates/relayer/src/lib.rs index 17668e69ea..8ef35e6629 100644 --- a/crates/relayer/src/lib.rs +++ b/crates/relayer/src/lib.rs @@ -36,7 +36,6 @@ pub mod foreign_client; pub mod keyring; pub mod light_client; pub mod link; -pub mod macros; pub mod misbehaviour; pub mod object; pub mod path; diff --git a/crates/relayer/src/macros.rs b/crates/relayer/src/macros.rs deleted file mode 100644 index f996a9b776..0000000000 --- a/crates/relayer/src/macros.rs +++ /dev/null @@ -1,126 +0,0 @@ -#[cfg(feature = "profiling")] -pub mod profiling { - - use core::sync::atomic::AtomicUsize; - use core::sync::atomic::Ordering::Relaxed; - use once_cell::sync::OnceCell; - use serde_derive::Serialize; - use serde_json::Value; - use std::fs::File; - use std::fs::OpenOptions; - use std::path::Path; - - std::thread_local! { - pub static DEPTH: AtomicUsize = AtomicUsize::new(0); - } - static FILE: OnceCell = OnceCell::new(); - - /// Measure the time between when this value is allocated - /// and when it is dropped. - pub struct Timer { - name: &'static str, - info: Value, - start: std::time::Instant, - } - - #[derive(Debug, Serialize)] - struct TimerInfo<'a> { - name: &'a str, - #[serde(flatten)] - info: &'a Value, - elapsed: u128, - } - - impl Timer { - pub fn new(name: &'static str, info: Value) -> Self { - let depth = DEPTH.with(|d| d.fetch_add(1, Relaxed)); - let pad = " ".repeat(depth); - - tracing::info!("{}⏳ {} - start", pad, name); - - Self { - name, - info, - start: std::time::Instant::now(), - } - } - } - - impl Drop for Timer { - fn drop(&mut self) { - let elapsed = self.start.elapsed().as_millis(); - - let depth = DEPTH.with(|d| d.fetch_sub(1, Relaxed)); - let pad = " ".repeat(depth - 1); - - tracing::info!("{}⏳ {} - elapsed: {}ms", pad, self.name, elapsed); - - let info = TimerInfo { - name: self.name, - info: &self.info, - elapsed, - }; - - to_json_format(&info); - } - } - - pub fn open_or_create_profile_file(file_name: &Path) { - let file = OpenOptions::new() - .write(true) - .append(true) - .create(true) - .open(file_name) - .unwrap(); - - match FILE.set(file) { - Ok(_) => tracing::trace!("profile file created at: {file_name:#?}"), - Err(e) => tracing::error!("profile file was already set with: {:#?}", e.metadata()), - } - } - - fn to_json_format(info: &TimerInfo<'_>) { - match FILE.get() { - Some(mut f) => { - if let Err(e) = serde_json::to_writer(&mut f, &info) { - tracing::error!("Couldn't write to file: {e}"); - } - } - None => tracing::debug!("File for profiling is not set"), - } - } -} - -/// Measure the time until the current scope ends. -/// -/// Only enabled when the "profiling" feature is enabled. -/// -/// ## Example -/// -/// ```rust -/// use ibc_relayer::time; -/// -/// let val1 = 1; -/// let val2 = 2; -/// time!("full scope", {"id1": val1, "id2": val2}); -/// -/// let x = { -/// time!("inner scope", {}); -/// -/// 42 -/// // "inner scope" timer ends here -/// }; -/// // "full scope" timer ends here -/// ``` -#[macro_export] -macro_rules! time { - ($name:expr, $info:tt) => { - #[cfg(feature = "profiling")] - let _timer = $crate::macros::profiling::Timer::new($name, ::serde_json::json!($info)); - }; - - ($name:expr) => { - #[cfg(feature = "profiling")] - let _timer = $crate::macros::profiling::Timer::new($name, ::serde_json::json!({})); - }; -} diff --git a/crates/relayer/src/util.rs b/crates/relayer/src/util.rs index e33fe52b57..589b2f5ff4 100644 --- a/crates/relayer/src/util.rs +++ b/crates/relayer/src/util.rs @@ -2,10 +2,12 @@ mod block_on; pub use block_on::{block_on, spawn_blocking}; pub mod collate; +pub mod debug_section; pub mod diff; pub mod iter; pub mod lock; pub mod pretty; +pub mod profiling; pub mod queue; pub mod retry; pub mod stream; diff --git a/crates/relayer/src/util/debug_section.rs b/crates/relayer/src/util/debug_section.rs new file mode 100644 index 0000000000..79fbaef5b6 --- /dev/null +++ b/crates/relayer/src/util/debug_section.rs @@ -0,0 +1,6 @@ +#[derive(Copy, Clone, Debug, PartialEq, Eq)] +pub enum DebugSection { + Rpc, + Profiling, + ProfilingJson, +} diff --git a/crates/relayer/src/util/profiling.rs b/crates/relayer/src/util/profiling.rs new file mode 100644 index 0000000000..c6310f95fc --- /dev/null +++ b/crates/relayer/src/util/profiling.rs @@ -0,0 +1,166 @@ +use std::fs::{File, OpenOptions}; +use std::path::Path; +use std::sync::atomic::{AtomicUsize, Ordering::Relaxed}; +use std::sync::Mutex; + +use once_cell::sync::OnceCell; +use serde_derive::Serialize; +use serde_json::Value; + +std::thread_local! { + pub static DEPTH: AtomicUsize = AtomicUsize::new(0); +} + +static FILE: OnceCell> = OnceCell::new(); +static ENABLED: AtomicUsize = AtomicUsize::new(0); + +const CONSOLE_MASK: usize = 0b01; +const JSON_MASK: usize = 0b10; + +pub fn enable(console: bool, json: bool) { + let console_mask = if console { CONSOLE_MASK } else { 0 }; + let json_mask = if json { JSON_MASK } else { 0 }; + + ENABLED.store(console_mask | json_mask, Relaxed); +} + +pub fn console_enabled() -> bool { + ENABLED.load(Relaxed) & CONSOLE_MASK != 0 +} + +pub fn json_enabled() -> bool { + ENABLED.load(Relaxed) & JSON_MASK != 0 +} + +fn enabled() -> usize { + ENABLED.load(Relaxed) +} + +/// Measure the time between when this value is allocated +/// and when it is dropped. +pub struct Timer { + name: &'static str, + info: Value, + start: std::time::Instant, +} + +#[derive(Debug, Serialize)] +struct TimerInfo<'a> { + name: &'a str, + #[serde(flatten)] + info: &'a Value, + elapsed: u128, +} + +impl Timer { + pub fn new(name: &'static str, info: Value) -> Self { + let depth = DEPTH.with(|d| d.fetch_add(1, Relaxed)); + let pad = " ".repeat(depth); + + if console_enabled() { + tracing::info!("{}⏳ {} - start", pad, name); + } + + Self { + name, + info, + start: std::time::Instant::now(), + } + } +} + +impl Drop for Timer { + fn drop(&mut self) { + let enabled = enabled(); + + if enabled == 0 { + return; + } + + let elapsed = self.start.elapsed().as_millis(); + + let depth = DEPTH.with(|d| d.fetch_sub(1, Relaxed)); + let pad = " ".repeat(depth - 1); + + if enabled & CONSOLE_MASK != 0 { + tracing::info!("{}⏳ {} - elapsed: {}ms", pad, self.name, elapsed); + } + + if enabled & JSON_MASK != 0 { + output_json(&TimerInfo { + name: self.name, + info: &self.info, + elapsed, + }); + } + } +} + +pub fn open_or_create_profile_file(file_name: &Path) { + let file = OpenOptions::new() + .write(true) + .append(true) + .create(true) + .open(file_name) + .unwrap(); + + match FILE.set(Mutex::new(file)) { + Ok(_) => tracing::trace!("profile file created at: {file_name:#?}"), + Err(e) => tracing::error!( + "profile file was already set with: {:#?}", + e.lock().unwrap().metadata() + ), + } +} + +fn output_json(info: &TimerInfo<'_>) { + if let Some(f) = FILE.get() { + if let Err(e) = _output_json(f, info) { + tracing::error!("couldn't write to file: {e}"); + } + } else { + tracing::debug!("File for profiling output is not set"); + } +} + +fn _output_json(f: &Mutex, info: &TimerInfo<'_>) -> Result<(), Box> { + use std::io::Write; + + let mut f = f.lock().unwrap(); + serde_json::to_writer(&mut *f, info)?; + writeln!(&mut *f)?; + + Ok(()) +} + +/// Measure the time until the current scope ends. +/// +/// Only enabled when "--debug=profiling" is set. +/// +/// ## Example +/// +/// ```rust +/// use ibc_relayer::time; +/// +/// let val1 = 1; +/// let val2 = 2; +/// time!("full scope", {"id1": val1, "id2": val2}); +/// +/// let x = { +/// time!("inner scope", {}); +/// +/// 42 +/// // "inner scope" timer ends here +/// }; +/// // "full scope" timer ends here +/// ``` +#[macro_export] +macro_rules! time { + ($name:expr, $info:tt) => { + let _timer = $crate::util::profiling::Timer::new($name, ::serde_json::json!($info)); + }; + + ($name:expr) => { + let _timer = $crate::util::profiling::Timer::new($name, ::serde_json::json!({})); + }; +} diff --git a/guide/src/advanced/troubleshooting/profiling.md b/guide/src/advanced/troubleshooting/profiling.md index 956011bbdd..cafc46642b 100644 --- a/guide/src/advanced/troubleshooting/profiling.md +++ b/guide/src/advanced/troubleshooting/profiling.md @@ -4,25 +4,12 @@ The `relayer` crate provides a `time!` macro which can be used to measure how mu ### Setup -The `time!` macro has no effect unless the `profiling` feature of the `relayer` crate is enabled. - -To enable it, one must compile the `relayer-cli` crate with the `--features=profiling` flag. - -a) One way is to build the `relayer` binary and update the `hermes` alias to point to the executable: +The `time!` macro has no effect unless the `--debug=profiling` global flag is specified on the command-line: ```shell -cd relayer-cli/ -cargo build --features=profiling +$ hermes --debug=profiling start ``` -b) Alternatively, one can use the `cargo run` command and update the alias accordingly: - -```shell -alias hermes='cargo run --features=profiling --manifest-path=relayer-cli/Cargo.toml --' -``` - -The `--manifest-path=relayer-cli/Cargo.toml` flag is needed for `cargo run` to accept the `--features` flag. - ### Example ```rust @@ -45,7 +32,7 @@ fn my_function(x: u32) -> u32 { } ``` -#### Output +#### Console output ``` Jan 20 11:28:46.841 INFO relayer::macros::profiling: ⏳ myfunction: x=42 - start @@ -60,10 +47,9 @@ and it's often not clear which of these are the culprit for low performance. With profiling enabled, `hermes` will output timing information for individual methods involved in a command. -__NOTE__: To be able to see the profiling output, Hermes needs to be compiled with -the `profiling` feature and the [log level][log-level] should be `info` level or lower. +__NOTE__: To be able to see the profiling output, the [log level][log-level] should be `info` level or lower. -#### Example output for `tx conn-init` command +##### Example output for `tx conn-init` command ``` {{#template ../../templates/commands/hermes/tx/conn-init_1.md DST_CHAIN_ID=ibc-0 SRC_CHAIN_ID=ibc-1 DST_CLIENT_ID=07-tendermint-0 SRC_CLIENT_ID=07-tendermint-0}} @@ -123,3 +109,26 @@ Success: CreateClient( ), ) ``` + +#### JSON output + +Additionally, if the `--debug=profiling-json` flag is specified, Hermes will output profiling information in +JSON format in a file named `hermes-YYYY-MM-DD-HHMMSS-prof.json`, in the directory specified in the `PROFILING_DIR` +env variable, or the current directory otherwise. + +> __NOTE__: Outputting profiling information in JSON format in a file is only available for the `hermes start` command. +> This debug option won't do anything with the other CLIs. + +```json +{"name":"fetch_node_info","src_chain":"ibc-0","elapsed":6} +{"name":"chain_status","src_chain":"ibc-0","elapsed":12} +{"name":"query_config_params","src_chain":"ibc-0","elapsed":3} +{"name":"min_gas_price","src_chain":"ibc-0","elapsed":3} +{"name":"query_staking_params","src_chain":"ibc-0","elapsed":159} +{"name":"historical_entries","src_chain":"ibc-0","elapsed":329} +{"name":"query_staking_params","src_chain":"ibc-0","elapsed":121} +{"name":"unbonding_period","src_chain":"ibc-0","elapsed":12} +{"name":"query_latest_height","src_chain":"ibc-0","elapsed":8} +{"name":"fetch_node_info","src_chain":"ibc-1","elapsed":9} +{"name":"chain_status","src_chain":"ibc-1","elapsed":43} +``` diff --git a/guide/src/templates/help_templates/help.md b/guide/src/templates/help_templates/help.md index 6c56d6d60d..516720fc78 100644 --- a/guide/src/templates/help_templates/help.md +++ b/guide/src/templates/help_templates/help.md @@ -7,6 +7,8 @@ USAGE: OPTIONS: --config Path to configuration file + --debug Enable debug output for the given section(s), comma separated, can be + repeated. [possible values: rpc, profiling, profiling-json] -h, --help Print help information --json Enable JSON output -V, --version Print version information diff --git a/scripts/auto_gen_templates.sh b/scripts/auto_gen_templates.sh index 5ad8363f5e..d7eb557357 100644 --- a/scripts/auto_gen_templates.sh +++ b/scripts/auto_gen_templates.sh @@ -185,6 +185,8 @@ function generate_templates(){ local dir="${tmp%/*}" mkdir -p $dir + echo "Generating template for command '$command'..." + local cpt=1 cargo run -q --bin hermes $command | $SED -n '/USAGE:/, /OPTIONS:/{ /USAGE:/! { /OPTIONS:/! p }}' | $SED -r '/^\s*$/d ; s/^\s+// ; s//]]/g; s/hermes/[[#BINARY hermes]][[#GLOBALOPTIONS]]/ ; s/ \[(OPTIONS|SUBCOMMAND)]/\[\[#\1]]/g ;' | while read line || [[ -n $line ]] do