Profiling
The relayer
crate provides a time!
macro which can be used to measure how much time is spent between the invocation of the macro and the end of the enclosing scope.
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:
cd relayer-cli/
cargo build --features=profiling
b) Alternatively, one can use the cargo run
command and update the alias accordingly:
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
#![allow(unused)] fn main() { fn my_function(x: u32) -> u32 { time!("myfunction: x={}", x); // A std::thread::sleep(Duration::from_secs(1)); { time!("inner operation"); // B std::thread::sleep(Duration::from_secs(2)); // timer B ends here } x + 1 // timer A ends here } }
Output
Jan 20 11:28:46.841 INFO relayer::macros::profiling: ⏳ myfunction: x=42 - start
Jan 20 11:28:47.842 INFO relayer::macros::profiling: ⏳ inner operation - start
Jan 20 11:28:49.846 INFO relayer::macros::profiling: ⏳ inner operation - elapsed: 2004ms
Jan 20 11:28:49.847 INFO relayer::macros::profiling: ⏳ myfunction: x=42 - elapsed: 3005ms
Profiling is useful for tracking down unusually slow methods.
Each transaction or query usually consists of multiple lower-level methods,
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.
Example output for tx conn-init
command
hermes tx conn-init --dst-chain ibc-0 --src-chain ibc-1 --dst-client 07-tendermint-0 --src-client 07-tendermint-0
Apr 13 20:58:21.225 INFO ibc_relayer::macros::profiling: ⏳ init_light_client - start
Apr 13 20:58:21.230 INFO ibc_relayer::macros::profiling: ⏳ init_light_client - elapsed: 4ms
Apr 13 20:58:21.230 INFO ibc_relayer::macros::profiling: ⏳ init_event_monitor - start
Apr 13 20:58:21.235 INFO ibc_relayer::macros::profiling: ⏳ init_event_monitor - elapsed: 5ms
Apr 13 20:58:21.235 INFO ibc_relayer::event::monitor: running listener chain.id=ibc-1
Apr 13 20:58:21.236 INFO ibc_relayer::macros::profiling: ⏳ init_light_client - start
Apr 13 20:58:21.239 INFO ibc_relayer::macros::profiling: ⏳ init_light_client - elapsed: 2ms
Apr 13 20:58:21.239 INFO ibc_relayer::macros::profiling: ⏳ init_event_monitor - start
Apr 13 20:58:21.244 INFO ibc_relayer::macros::profiling: ⏳ init_event_monitor - elapsed: 4ms
Apr 13 20:58:21.244 INFO ibc_relayer::event::monitor: running listener chain.id=ibc-0
Apr 13 20:58:21.244 INFO ibc_relayer::macros::profiling: ⏳ get_signer - start
Apr 13 20:58:21.246 INFO ibc_relayer::macros::profiling: ⏳ get_signer - elapsed: 1ms
Apr 13 20:58:21.246 INFO ibc_relayer::macros::profiling: ⏳ query_latest_height - start
Apr 13 20:58:21.246 INFO ibc_relayer::macros::profiling: ⏳ block_on - start
Apr 13 20:58:21.248 INFO ibc_relayer::macros::profiling: ⏳ block_on - elapsed: 1ms
Apr 13 20:58:21.249 INFO ibc_relayer::macros::profiling: ⏳ query_latest_height - elapsed: 3ms
Apr 13 20:58:21.250 INFO ibc_relayer::macros::profiling: ⏳ unbonding_period - start
Apr 13 20:58:21.250 INFO ibc_relayer::macros::profiling: ⏳ block_on - start
Apr 13 20:58:21.251 INFO ibc_relayer::macros::profiling: ⏳ block_on - elapsed: 0ms
Apr 13 20:58:21.270 INFO ibc_relayer::macros::profiling: ⏳ block_on - start
Apr 13 20:58:21.273 INFO ibc_relayer::macros::profiling: ⏳ block_on - elapsed: 2ms
Apr 13 20:58:21.273 INFO ibc_relayer::macros::profiling: ⏳ unbonding_period - elapsed: 23ms
Apr 13 20:58:21.279 INFO ibc_relayer::macros::profiling: ⏳ build_consensus_state - start
Apr 13 20:58:21.280 INFO ibc_relayer::macros::profiling: ⏳ build_consensus_state - elapsed: 0ms
Apr 13 20:58:21.280 INFO ibc_relayer::macros::profiling: ⏳ send_msgs - start
Apr 13 20:58:21.280 INFO ibc_relayer::macros::profiling: ⏳ send_tx - start
Apr 13 20:58:21.282 INFO ibc_relayer::macros::profiling: ⏳ PK "03f17d2c094ee68cfcedb2c2f2b7dec6cd82ea158ac1c32d3de0ca8b288a3c8bfa" - start
Apr 13 20:58:21.282 INFO ibc_relayer::macros::profiling: ⏳ block_on - start
Apr 13 20:58:21.285 INFO ibc_relayer::macros::profiling: ⏳ block_on - elapsed: 3ms
Apr 13 20:58:21.296 INFO ibc_relayer::macros::profiling: ⏳ block_on - start
Apr 13 20:58:22.664 INFO ibc_relayer::macros::profiling: ⏳ block_on - elapsed: 1367ms
Apr 13 20:58:22.664 INFO ibc_relayer::macros::profiling: ⏳ PK "03f17d2c094ee68cfcedb2c2f2b7dec6cd82ea158ac1c32d3de0ca8b288a3c8bfa" - elapsed: 1382ms
Apr 13 20:58:22.664 INFO ibc_relayer::macros::profiling: ⏳ send_tx - elapsed: 1384ms
Apr 13 20:58:22.664 INFO ibc_relayer::macros::profiling: ⏳ send_msgs - elapsed: 1384ms
Success: CreateClient(
CreateClient(
Attributes {
height: Height {
revision: 0,
height: 10675,
},
client_id: ClientId(
"07-tendermint-7",
),
client_type: Tendermint,
consensus_height: Height {
revision: 1,
height: 10663,
},
},
),
)