From 8a79d35c6cd56ca80f7266faf2b02068c016ffe6 Mon Sep 17 00:00:00 2001 From: Romain Ruetschi Date: Wed, 20 Jan 2021 11:55:13 +0100 Subject: [PATCH] Restore calls to self.block_on in cosmos chain impl (#539) * Introduce time! macro to measure time spent in a scope * Restore calls to self.block_on in cosmos chain impl * Fix doc test * Simplify signature of CosmosSDKChain::block_on * Update changelog * Cleanup relayer operation instructions * Add profiling instructions to the operation instructions * Trim trailing whitespaces in operation instructions * Update instructions to checkout Gaia v3.0.0 Co-authored-by: Anca Zamfir Co-authored-by: Anca Zamfir --- CHANGELOG.md | 9 +- relayer-cli/Cargo.toml | 4 + relayer-cli/relayer_operation_instructions.md | 357 ++++++++++++------ relayer/Cargo.toml | 3 + relayer/src/chain/cosmos.rs | 118 ++++-- relayer/src/lib.rs | 1 + relayer/src/macros.rs | 69 ++++ 7 files changed, 405 insertions(+), 156 deletions(-) create mode 100644 relayer/src/macros.rs diff --git a/CHANGELOG.md b/CHANGELOG.md index 52eb5d5daf..b1ccd774cb 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -20,17 +20,17 @@ - Add `packet-send` CLI ([#470]) - [relayer] - - Performance improvements ([#514]) + - Performance improvements ([#514], [#537]) - Fix for mismatching `bitcoin` dep ([#525]) - [modules] - - Clean the validate_basic method ([#94]) - - MsgConnectionOpenAck testing improvements ([#306]) + - Clean the `validate_basic` method ([#94]) + - `MsgConnectionOpenAck` testing improvements ([#306]) ### BUG FIXES: - [modules] - - Fix for storing ClientType upon 'create-client' ([#513]) + - Fix for storing `ClientType` upon 'create-client' ([#513]) [#94]: https://github.com/informalsystems/ibc-rs/issues/94 [#306]: https://github.com/informalsystems/ibc-rs/issues/306 @@ -44,6 +44,7 @@ [#517]: https://github.com/informalsystems/ibc-rs/issues/517 [#525]: https://github.com/informalsystems/ibc-rs/issues/525 [#527]: https://github.com/informalsystems/ibc-rs/issues/527 +[#537]: https://github.com/informalsystems/ibc-rs/issues/537 ## v0.0.6 diff --git a/relayer-cli/Cargo.toml b/relayer-cli/Cargo.toml index 2dd11ab879..3cbacd473a 100644 --- a/relayer-cli/Cargo.toml +++ b/relayer-cli/Cargo.toml @@ -6,10 +6,14 @@ authors = [ "Informal Systems " ] +[features] +profiling = ["relayer/profiling"] + [dependencies] relayer = { path = "../relayer" } ibc = { path = "../modules" } ibc-proto = { version = "0.6.0", path = "../proto" } + anomaly = "0.2.0" gumdrop = "0.7" serde = { version = "1", features = ["serde_derive"] } diff --git a/relayer-cli/relayer_operation_instructions.md b/relayer-cli/relayer_operation_instructions.md index 77e73de1b9..ca672ff795 100644 --- a/relayer-cli/relayer_operation_instructions.md +++ b/relayer-cli/relayer_operation_instructions.md @@ -1,101 +1,136 @@ +## Relayer operation instructions ### Gaia - 1. Clone gaia: -```shell script -git clone https://github.com/cosmos/gaia.git ~/go/src/github.com/comsos/gaia -~/go/src/github.com/comsos/gaia ; git co new-main ; make install -``` - 2. Start the gaia instances by running the `dev-env` script from the `ibc-rs` repo: -```shell script -./dev-env -``` -e.g.: -```shell script -./dev-env my_config.toml ibc-0 ibc-1 -``` +1. Clone gaia: + + ```shell script + git clone https://github.com/cosmos/gaia.git ~/go/src/github.com/comsos/gaia + ~/go/src/github.com/comsos/gaia ; git co v3.0.0 ; make install + ``` + +2. Start the gaia instances by running the `dev-env` script from the `ibc-rs` repo: + + ```shell script + ./dev-env + ``` + e.g.: + + ```shell + ./dev-env my_config.toml ibc-0 ibc-1 + ``` ### CLI Step Relaying: -You can use the relayer CLIs, below are some examples. -Note: `alias rrly='cargo run --bin relayer --'` -#### Client CLIs: - - create client: -```shell script -rrly -c loop_config.toml tx raw create-client ibc-0 ibc-1 -rrly -c loop_config.toml tx raw create-client ibc-1 ibc-0 +You can use the relayer CLIs, below are some examples. -rrly -c loop_config.toml query client state ibc-0 07-tendermint-0 -rrly -c loop_config.toml query client state ibc-1 07-tendermint-0 -``` +**Note:** These instructions below assume that the `relayer-cli` binary +can be executed as `rrly`, eg. by using an shell alias: - - update client - ```shell script -rrly -c loop_config.toml tx raw update-client ibc-0 ibc-1 07-tendermint-0 -rrly -c loop_config.toml tx raw update-client ibc-1 ibc-0 07-tendermint-0 +alias rrly='cargo run --bin relayer --'` ``` + +#### Client CLIs: + +- create client: + + ```shell script + rrly -c loop_config.toml tx raw create-client ibc-0 ibc-1 + rrly -c loop_config.toml tx raw create-client ibc-1 ibc-0 + + rrly -c loop_config.toml query client state ibc-0 07-tendermint-0 + rrly -c loop_config.toml query client state ibc-1 07-tendermint-0 + ``` + +- update client + + ```shell script + rrly -c loop_config.toml tx raw update-client ibc-0 ibc-1 07-tendermint-0 + rrly -c loop_config.toml tx raw update-client ibc-1 ibc-0 07-tendermint-0 + ``` + #### Connection CLIs: - - init-none: -```shell script -rrly -c loop_config.toml tx raw conn-init ibc-0 ibc-1 07-tendermint-0 07-tendermint-0 dummyconnection dummyconnection -``` -Take note of the ID allocated by the chain, e.g. `connection-0` on `ibc-0`. Use in the `conn-try` CLI +- init-none: - - init-try: -```shell script -rrly -c loop_config.toml tx raw conn-try ibc-1 ibc-0 07-tendermint-0 07-tendermint-0 dummyconnection connection-0 -``` -Take note of the ID allocated by the chain, e.g. `connection-0` on `ibc-1`. Use in the `conn-ack` CLI + ```shell script + rrly -c loop_config.toml tx raw conn-init ibc-0 ibc-1 07-tendermint-0 07-tendermint-0 dummyconnection dummyconnection + ``` - - open-try: -```shell script -rrly -c loop_config.toml tx raw conn-ack ibc-0 ibc-1 07-tendermint-0 07-tendermint-0 connection-0 connection-0 -``` - - open-open: -```shell script -rrly -c loop_config.toml tx raw conn-confirm ibc-1 ibc-0 07-tendermint-0 07-tendermint-0 connection-0 connection-0 -``` - - verify that the two ends are in Open state: -```shell script -rrly -c loop_config.toml query connection end ibc-1 connection-0 -rrly -c loop_config.toml query connection end ibc-0 connection-0 -``` + Take note of the ID allocated by the chain, e.g. `connection-0` on `ibc-0`. Use in the `conn-try` CLI + +- init-try: + + ```shell script + rrly -c loop_config.toml tx raw conn-try ibc-1 ibc-0 07-tendermint-0 07-tendermint-0 dummyconnection connection-0 + ``` + + Take note of the ID allocated by the chain, e.g. `connection-0` on `ibc-1`. Use in the `conn-ack` CLI + +- open-try: + + ```shell script + rrly -c loop_config.toml tx raw conn-ack ibc-0 ibc-1 07-tendermint-0 07-tendermint-0 connection-0 connection-0 + ``` + +- open-open: + + ```shell script + rrly -c loop_config.toml tx raw conn-confirm ibc-1 ibc-0 07-tendermint-0 07-tendermint-0 connection-0 connection-0 + ``` + +- verify that the two ends are in Open state: + + ```shell script + rrly -c loop_config.toml query connection end ibc-1 connection-0 + rrly -c loop_config.toml query connection end ibc-0 connection-0 + ``` #### Channel CLIs: - - init-none -```shell script -rrly -c loop_config.toml tx raw chan-init ibc-0 ibc-1 connection-0 transfer transfer defaultChannel defaultChannel -``` - - init-try -```shell script -rrly -c loop_config.toml tx raw chan-try ibc-1 ibc-0 connection-0 transfer transfer defaultChannel channel-0 -``` - - open-try -```shell script -rrly -c loop_config.toml tx raw chan-ack ibc-0 ibc-1 connection-0 transfer transfer channel-0 channel-0 -``` - - open-open -```shell script -rrly -c loop_config.toml tx raw chan-confirm ibc-1 ibc-0 connection-0 transfer transfer channel-0 channel-0 -``` - - verify that the two ends are in Open state: -```shell script -rrly -c loop_config.toml query channel end ibc-0 transfer channel-0 -rrly -c loop_config.toml query channel end ibc-1 transfer channel-0 -``` + +- init-none + + ```shell script + rrly -c loop_config.toml tx raw chan-init ibc-0 ibc-1 connection-0 transfer transfer defaultChannel defaultChannel + ``` +- init-try + + ```shell script + rrly -c loop_config.toml tx raw chan-try ibc-1 ibc-0 connection-0 transfer transfer defaultChannel channel-0 + ``` + +- open-try + + ```shell script + rrly -c loop_config.toml tx raw chan-ack ibc-0 ibc-1 connection-0 transfer transfer channel-0 channel-0 + ``` +- open-open + + ```shell script + rrly -c loop_config.toml tx raw chan-confirm ibc-1 ibc-0 connection-0 transfer transfer channel-0 channel-0 + ``` + +- verify that the two ends are in Open state: + + ```shell script + rrly -c loop_config.toml query channel end ibc-0 transfer channel-0 + rrly -c loop_config.toml query channel end ibc-1 transfer channel-0 + ``` #### Query balances: - - balance at ibc-0 -```shell script -gaiad --node tcp://localhost:26657 query bank balances $(gaiad --home data/ibc-0 keys --keyring-backend="test" show user -a) -``` - - balance at ibc-1 -```shell script -gaiad --node tcp://localhost:26557 query bank balances $(gaiad --home data/ibc-1 keys --keyring-backend="test" show user -a) -``` +- balance at ibc-0 + + ```shell script + gaiad --node tcp://localhost:26657 query bank balances $(gaiad --home data/ibc-0 keys --keyring-backend="test" show user -a) + ``` + +- balance at ibc-1 + + ```shell script + gaiad --node tcp://localhost:26557 query bank balances $(gaiad --home data/ibc-1 keys --keyring-backend="test" show user -a) + ``` Note that the addresses used in the two commands above are configured in `dev-env`. @@ -103,34 +138,47 @@ Note that the addresses used in the two commands above are configured in `dev-en First, we'll send 9999 samoleans from `ibc-0` to `ibc-1`. - - send 1 packet to ibc-0 -```shell script -rrly -c loop_config.toml tx raw packet-send ibc-0 ibc-1 transfer channel-0 9999 1000 -n 1 -d samoleans -``` - - query unrecevied packets on ibc-1 -```shell script -rrly -c loop_config.toml query packet unreceived-packets ibc-1 ibc-0 transfer channel-0 -``` - - send recv_packet to ibc-1 -```shell script -rrly -c loop_config.toml tx raw packet-recv ibc-0 ibc-1 07-tendermint-0 07-tendermint-0 transfer transfer channel-0 channel-0 -``` - - query unreceived acks on ibc-0 -```shell script -rrly -c loop_config.toml query packet unreceived-acks ibc-0 ibc-1 transfer channel-0 -``` - - send acknowledgement to ibc-0 -```shell script -rrly -c loop_config.toml tx raw packet-ack ibc-0 ibc-1 07-tendermint-0 07-tendermint-0 transfer transfer channel-0 channel-0 -``` - - send 1 packet with low timeout height offset to ibc-0 -```shell script -rrly -c loop_config.toml tx raw packet-send ibc-0 ibc-1 transfer channel-0 9999 2 -n 1 -``` - - send timeout to ibc-0 -```shell script -rrly -c loop_config.toml tx raw packet-recv ibc-0 ibc-1 07-tendermint-0 07-tendermint-0 transfer transfer channel-0 channel-0 -``` +- send 1 packet to ibc-0 + + ```shell script + rrly -c loop_config.toml tx raw packet-send ibc-0 ibc-1 transfer channel-0 9999 1000 -n 1 -d samoleans + ``` + +- query unreceived packets on ibc-1 + + ```shell script + rrly -c loop_config.toml query packet unreceived-packets ibc-1 ibc-0 transfer channel-0 + ``` + +- send recv_packet to ibc-1 + + ```shell script + rrly -c loop_config.toml tx raw packet-recv ibc-0 ibc-1 07-tendermint-0 07-tendermint-0 transfer transfer channel-0 channel-0 + ``` + +- query unreceived acks on ibc-0 + + ```shell script + rrly -c loop_config.toml query packet unreceived-acks ibc-0 ibc-1 transfer channel-0 + ``` + +- send acknowledgement to ibc-0 + + ```shell script + rrly -c loop_config.toml tx raw packet-ack ibc-0 ibc-1 07-tendermint-0 07-tendermint-0 transfer transfer channel-0 channel-0 + ``` + +- send 1 packet with low timeout height offset to ibc-0 + + ```shell script + rrly -c loop_config.toml tx raw packet-send ibc-0 ibc-1 transfer channel-0 9999 2 -n 1 + ``` + +- send timeout to ibc-0 + + ```shell script + rrly -c loop_config.toml tx raw packet-recv ibc-0 ibc-1 07-tendermint-0 07-tendermint-0 transfer transfer channel-0 channel-0 + ``` Now, we'll send those samoleans back, from `ibc-1` to `ibc-1`. @@ -142,27 +190,92 @@ rrly -c loop_config.toml tx raw packet-ack ibc-1 ibc-0 07-tendermint-0 07-tende The `ibc/27A6394C3F9FF9C9DCF5DFFADF9BB5FE9A37C7E92B006199894CF1824DF9AC7C` denominator above can be obtained by querying the balance at `ibc-1` after the transfer from `ibc-0` to `ibc-1` is concluded. -### Relayer loop: +### Relayer loop: + Client, connection, channel handshake and packet relaying can pe done from the relayer loop - - start the relayer, the relayer should create the clients, and do the handshake for the connection and channel. Once that is done it will sit in a loop, listening for events +- start the relayer, the relayer should create the clients, and do the handshake for the connection and channel. Once that is done it will sit in a loop, listening for events + + ```shell script + rrly -c loop_config.toml v-0 + ``` + +- use the CLI to send 2 packets to ibc0 chain: + + ```shell script + rrly -c loop_config.toml tx raw packet-send ibc-0 ibc-1 transfer channel-0 9999 1000 -n 2 + ``` +- use the CLI to send 2 packets to ibc0 chain: + + ```shell script + rrly -c loop_config.toml tx raw packet-send ibc-1 ibc-2 transfer channel-0 9999 1000 -n 2 + ``` + +- observe the output on the relayer terminal, verify that the send events are processed and the recv_packets are sent out. + +- query the unreceived packets on ibc0 and ibc1 from a different terminal + + ```shell script + rrly -c loop_config.toml query packet unreceived-packets ibc-1 ibc-0 transfer channel-0 + rrly -c loop_config.toml query packet unreceived-acks ibc-0 ibc-1 transfer channel-0 + rrly -c loop_config.toml query packet unreceived-packets ibc-0 ibc-1 transfer channel-0 + rrly -c loop_config.toml query packet unreceived-acks ibc-1 ibc-0 transfer channel-0 + ``` + +## Profiling the relayer + +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 `rrly` alias to point to the executable: + ```shell script -rrly -c loop_config.toml v-0 +$ cd relayer-cli/ +$ cargo build --features=profiling +$ cd .. +$ alias rrly=target/debug/relayer ``` - - use the CLI to send 2 packets to ibc0 chain: + +b) Alternatively, one can use the `cargo run` command and update the alias accordingly: + ```shell script -rrly -c loop_config.toml tx raw packet-send ibc-0 ibc-1 transfer channel-0 9999 1000 -n 2 +$ alias rrly='cargo run --features=profiling --manifest-path=relayer-cli/Cargo.toml --' ``` - - use the CLI to send 2 packets to ibc0 chain: -```shell script -rrly -c loop_config.toml tx raw packet-send ibc-1 ibc-2 transfer channel-0 9999 1000 -n 2 + +The `--manifest-path=relayer-cli/Cargo.toml` flag is needed for `cargo run` to accept the `--features` flag. + +### Example + +```rust +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 +} ``` - - observe the output on the relayer terminal, verify that the send events are processed and the recv_packets are sent out. - - query the unreceived packets on ibc0 and ibc1 from a different terminal -```shell script -rrly -c loop_config.toml query packet unreceived-packets ibc-1 ibc-0 transfer channel-0 -rrly -c loop_config.toml query packet unreceived-acks ibc-0 ibc-1 transfer channel-0 -rrly -c loop_config.toml query packet unreceived-packets ibc-0 ibc-1 transfer channel-0 -rrly -c loop_config.toml query packet unreceived-acks ibc-1 ibc-0 transfer channel-0 +#### 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 ``` diff --git a/relayer/Cargo.toml b/relayer/Cargo.toml index e34fec7a61..0d152f1981 100644 --- a/relayer/Cargo.toml +++ b/relayer/Cargo.toml @@ -6,6 +6,9 @@ authors = [ "Informal Systems " ] +[features] +profiling = [] + [dependencies] subtle-encoding = "0.5" ibc = { path = "../modules" } diff --git a/relayer/src/chain/cosmos.rs b/relayer/src/chain/cosmos.rs index d722237710..3dbb05cbe2 100644 --- a/relayer/src/chain/cosmos.rs +++ b/relayer/src/chain/cosmos.rs @@ -62,7 +62,6 @@ use crate::event::monitor::{EventBatch, EventMonitor}; use crate::keyring::store::{KeyEntry, KeyRing, KeyRingOperations, StoreBackend}; use crate::light_client::tendermint::LightClient as TMLightClient; use crate::light_client::LightClient; -use crate::util::block_on; use ibc::ics04_channel::packet::Sequence; // TODO size this properly @@ -80,6 +79,8 @@ pub struct CosmosSDKChain { impl CosmosSDKChain { /// The unbonding period of this chain pub fn unbonding_period(&self) -> Result { + crate::time!("unbonding_period"); + // TODO - generalize this let grpc_addr = Uri::from_str(&self.config().grpc_addr).map_err(|e| Kind::Grpc.context(e))?; @@ -87,13 +88,15 @@ impl CosmosSDKChain { let mut client = self .block_on( ibc_proto::cosmos::staking::v1beta1::query_client::QueryClient::connect(grpc_addr), - )? + ) .map_err(|e| Kind::Grpc.context(e))?; let request = tonic::Request::new(ibc_proto::cosmos::staking::v1beta1::QueryParamsRequest {}); - let response = block_on(client.params(request)).map_err(|e| Kind::Grpc.context(e))?; + let response = self + .block_on(client.params(request)) + .map_err(|e| Kind::Grpc.context(e))?; let res = response .into_inner() @@ -116,21 +119,28 @@ impl CosmosSDKChain { /// Query the consensus parameters via an RPC query /// Specific to the SDK and used only for Tendermint client create pub fn query_consensus_params(&self) -> Result { - Ok(block_on(self.rpc_client().genesis()) + crate::time!("query_consensus_params"); + + Ok(self + .block_on(self.rpc_client().genesis()) .map_err(|e| Kind::Rpc.context(e))? .consensus_params) } /// Run a future to completion on the Tokio runtime. - fn block_on(&self, f: F) -> Result { - Ok(self.rt.block_on(f)) + fn block_on(&self, f: F) -> F::Output { + crate::time!("block_on"); + self.rt.block_on(f) } fn send_tx(&self, proto_msgs: Vec) -> Result, Error> { + crate::time!("send_tx"); + let key = self .keybase() .get_key() .map_err(|e| Kind::KeyBase.context(e))?; + // Create TxBody let body = TxBody { messages: proto_msgs.to_vec(), @@ -153,8 +163,9 @@ impl CosmosSDKChain { value: pk_buf, }; - let acct_response = - block_on(query_account(self, key.account)).map_err(|e| Kind::Grpc.context(e))?; + let acct_response = self + .block_on(query_account(self, key.account)) + .map_err(|e| Kind::Grpc.context(e))?; let single = Single { mode: 1 }; let sum_single = Some(Sum::Single(single)); @@ -210,8 +221,9 @@ impl CosmosSDKChain { let mut txraw_buf = Vec::new(); prost::Message::encode(&tx_raw, &mut txraw_buf).unwrap(); - let response = - block_on(broadcast_tx_commit(self, txraw_buf)).map_err(|e| Kind::Rpc.context(e))?; + let response = self + .block_on(broadcast_tx_commit(self, txraw_buf)) + .map_err(|e| Kind::Rpc.context(e))?; let res = tx_result_to_event(response)?; @@ -258,6 +270,8 @@ impl Chain for CosmosSDKChain { fn init_light_client( &self, ) -> Result<(Box>, Option>), Error> { + crate::time!("init_light_client"); + let (lc, supervisor) = TMLightClient::from_config(&self.config, true)?; let supervisor_thread = thread::spawn(move || supervisor.run().unwrap()); @@ -275,6 +289,8 @@ impl Chain for CosmosSDKChain { ), Error, > { + crate::time!("init_event_monitor"); + let (mut event_monitor, event_receiver) = EventMonitor::new(self.config.id.clone(), self.config.rpc_addr.clone(), rt)?; @@ -293,6 +309,8 @@ impl Chain for CosmosSDKChain { } fn query(&self, data: Path, height: ICSHeight, prove: bool) -> Result { + crate::time!("query"); + let path = TendermintABCIPath::from_str(IBC_QUERY_PATH).unwrap(); let height = @@ -304,7 +322,7 @@ impl Chain for CosmosSDKChain { .into()); } - let response = block_on(abci_query(&self, path, data.to_string(), height, prove))?; + let response = self.block_on(abci_query(&self, path, data.to_string(), height, prove))?; // TODO - Verify response proof, if requested. if prove {} @@ -314,6 +332,8 @@ impl Chain for CosmosSDKChain { /// Send one or more transactions that include all the specified messages fn send_msgs(&mut self, proto_msgs: Vec) -> Result, Error> { + crate::time!("send_msgs"); + if proto_msgs.is_empty() { return Ok(vec![IBCEvent::Empty("No messages to send".to_string())]); } @@ -346,7 +366,11 @@ impl Chain for CosmosSDKChain { /// Query the latest height the chain is at via a RPC query fn query_latest_height(&self) -> Result { - let status = block_on(self.rpc_client().status()).map_err(|e| Kind::Rpc.context(e))?; + crate::time!("query_latest_height"); + + let status = self + .block_on(self.rpc_client().status()) + .map_err(|e| Kind::Rpc.context(e))?; if status.sync_info.catching_up { fail!( @@ -368,6 +392,8 @@ impl Chain for CosmosSDKChain { client_id: &ClientId, height: ICSHeight, ) -> Result { + crate::time!("query_client_state"); + let client_state = self .query(ClientStatePath(client_id.clone()), height, false) .map_err(|e| Kind::Query("client state".into()).context(e)) @@ -383,6 +409,8 @@ impl Chain for CosmosSDKChain { } fn query_commitment_prefix(&self) -> Result { + crate::time!("query_commitment_prefix"); + // TODO - do a real chain query Ok(CommitmentPrefix::from( self.config().store_prefix.as_bytes().to_vec(), @@ -394,6 +422,8 @@ impl Chain for CosmosSDKChain { client_id: &ClientId, height: ICSHeight, ) -> Result<(Self::ClientState, MerkleProof), Error> { + crate::time!("proven_client_state"); + let res = self .query(ClientStatePath(client_id.clone()), height, true) .map_err(|e| Kind::Query("client state".into()).context(e))?; @@ -420,6 +450,8 @@ impl Chain for CosmosSDKChain { consensus_height: ICSHeight, height: ICSHeight, ) -> Result<(Self::ConsensusState, MerkleProof), Error> { + crate::time!("proven_client_consensus"); + let res = self .query( ClientConsensusPath { @@ -469,6 +501,8 @@ impl Chain for CosmosSDKChain { &self, light_block: Self::LightBlock, ) -> Result { + crate::time!("build_consensus_state"); + Ok(TMConsensusState::from(light_block.signed_header.header)) } @@ -477,6 +511,8 @@ impl Chain for CosmosSDKChain { trusted_light_block: Self::LightBlock, target_light_block: Self::LightBlock, ) -> Result { + crate::time!("build_header"); + let trusted_height = ICSHeight::new(self.id().version(), trusted_light_block.height().into()); @@ -490,6 +526,8 @@ impl Chain for CosmosSDKChain { /// Get the account for the signer fn get_signer(&mut self) -> Result { + crate::time!("get_signer"); + // Get the key from key seed file let key = self .keybase() @@ -504,6 +542,8 @@ impl Chain for CosmosSDKChain { /// Get the signing key fn get_key(&mut self) -> Result { + crate::time!("get_key"); + // Get the key from key seed file let key = self .keybase() @@ -517,17 +557,20 @@ impl Chain for CosmosSDKChain { &self, request: QueryPacketCommitmentsRequest, ) -> Result<(Vec, ICSHeight), Error> { + crate::time!("query_packet_commitments"); + let grpc_addr = Uri::from_str(&self.config().grpc_addr).map_err(|e| Kind::Grpc.context(e))?; let mut client = self .block_on( ibc_proto::ibc::core::channel::v1::query_client::QueryClient::connect(grpc_addr), - )? + ) .map_err(|e| Kind::Grpc.context(e))?; let request = tonic::Request::new(request); - let response = block_on(client.packet_commitments(request)) + let response = self + .block_on(client.packet_commitments(request)) .map_err(|e| Kind::Grpc.context(e))? .into_inner(); @@ -547,17 +590,20 @@ impl Chain for CosmosSDKChain { &self, request: QueryUnreceivedPacketsRequest, ) -> Result, Error> { + crate::time!("query_unreceived_packets"); + let grpc_addr = Uri::from_str(&self.config().grpc_addr).map_err(|e| Kind::Grpc.context(e))?; let mut client = self .block_on( ibc_proto::ibc::core::channel::v1::query_client::QueryClient::connect(grpc_addr), - )? + ) .map_err(|e| Kind::Grpc.context(e))?; let request = tonic::Request::new(request); - let response = block_on(client.unreceived_packets(request)) + let response = self + .block_on(client.unreceived_packets(request)) .map_err(|e| Kind::Grpc.context(e))? .into_inner(); @@ -569,17 +615,20 @@ impl Chain for CosmosSDKChain { &self, request: QueryPacketAcknowledgementsRequest, ) -> Result<(Vec, ICSHeight), Error> { + crate::time!("query_packet_acknowledgements"); + let grpc_addr = Uri::from_str(&self.config().grpc_addr).map_err(|e| Kind::Grpc.context(e))?; let mut client = self .block_on( ibc_proto::ibc::core::channel::v1::query_client::QueryClient::connect(grpc_addr), - )? + ) .map_err(|e| Kind::Grpc.context(e))?; let request = tonic::Request::new(request); - let response = block_on(client.packet_acknowledgements(request)) + let response = self + .block_on(client.packet_acknowledgements(request)) .map_err(|e| Kind::Grpc.context(e))? .into_inner(); @@ -599,17 +648,20 @@ impl Chain for CosmosSDKChain { &self, request: QueryUnreceivedAcksRequest, ) -> Result, Error> { + crate::time!("query_unreceived_acknowledgements"); + let grpc_addr = Uri::from_str(&self.config().grpc_addr).map_err(|e| Kind::Grpc.context(e))?; let mut client = self .block_on( ibc_proto::ibc::core::channel::v1::query_client::QueryClient::connect(grpc_addr), - )? + ) .map_err(|e| Kind::Grpc.context(e))?; let request = tonic::Request::new(request); - let response = block_on(client.unreceived_acks(request)) + let response = self + .block_on(client.unreceived_acks(request)) .map_err(|e| Kind::Grpc.context(e))? .into_inner(); @@ -624,17 +676,21 @@ impl Chain for CosmosSDKChain { /// Therefore, here we perform one tx_search for each query. Alternatively, a single query /// for all packets could be performed but it would return all packets ever sent. fn query_txs(&self, request: QueryPacketEventDataRequest) -> Result, Error> { + crate::time!("query_txs"); + let mut result: Vec = vec![]; + for seq in request.sequences.iter() { // query all Tx-es that include events related to packet with given port, channel and sequence - let response = block_on(self.rpc_client.tx_search( - packet_query(&request, seq)?, - false, - 1, - 1, - Order::Ascending, - )) - .unwrap(); // todo + let response = self + .block_on(self.rpc_client.tx_search( + packet_query(&request, seq)?, + false, + 1, + 1, + Order::Ascending, + )) + .unwrap(); // todo let mut events = packet_from_tx_search_response(&request, *seq, &response)? .map_or(vec![], |v| vec![v]); @@ -647,18 +703,20 @@ impl Chain for CosmosSDKChain { &self, request: QueryConnectionChannelsRequest, ) -> Result, Error> { + crate::time!("query_connection_channels"); + let grpc_addr = Uri::from_str(&self.config().grpc_addr).map_err(|e| Kind::Grpc.context(e))?; let mut client = self .block_on( ibc_proto::ibc::core::channel::v1::query_client::QueryClient::connect(grpc_addr), - )? + ) .map_err(|e| Kind::Grpc.context(e))?; let request = tonic::Request::new(request); let response = self - .block_on(client.connection_channels(request))? + .block_on(client.connection_channels(request)) .map_err(|e| Kind::Grpc.context(e))? .into_inner(); diff --git a/relayer/src/lib.rs b/relayer/src/lib.rs index e34295460c..7342cedf82 100644 --- a/relayer/src/lib.rs +++ b/relayer/src/lib.rs @@ -24,6 +24,7 @@ pub mod keyring; pub mod keys; pub mod light_client; pub mod link; +pub mod macros; pub mod relay; pub mod transfer; pub mod util; diff --git a/relayer/src/macros.rs b/relayer/src/macros.rs new file mode 100644 index 0000000000..a1ac83b363 --- /dev/null +++ b/relayer/src/macros.rs @@ -0,0 +1,69 @@ +#[cfg(feature = "profiling")] +pub mod profiling { + + use std::sync::atomic::AtomicUsize; + use std::sync::atomic::Ordering::Relaxed; + + std::thread_local! { + pub static DEPTH: AtomicUsize = AtomicUsize::new(0); + } + + /// Measure the time between when this value is allocated + /// and when it is dropped. + pub struct Timer { + name: String, + start: std::time::Instant, + } + + impl Timer { + pub fn new(name: String) -> Self { + let depth = DEPTH.with(|d| d.fetch_add(1, Relaxed)); + let pad = " ".repeat(depth); + + tracing::info!("{}⏳ {} - start", pad, name); + + Self { + name, + 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); + } + } +} + +/// Measure the time until the current scope ends. +/// +/// Only enabled when the "profiling" is enabled. +/// +/// ## Example +/// +/// ```rust +/// use relayer::time; +/// +/// time!("full scope"); +/// +/// let x = { +/// time!("inner {}", "scope"); +/// +/// 42 +/// // "inner scope" timer ends here +/// }; +/// // "full scope" timer ends here +/// ``` +#[macro_export] +macro_rules! time { + ($($arg:tt)*) => { + #[cfg(feature = "profiling")] + let _timer = $crate::macros::profiling::Timer::new(format!($($arg)*)); + }; +}