perf(wasm): log RPC calls latency

[sergey-melnychuk]

This PR adds logging (into a browser's console when running Beerus through WebAssembly) of RPC calls latency, both to Ethereum via Helios and to Starknet. Any logging outside of wasm context is out of scope of this PR.

[sergey-melnychuk]

Logs produced by running built-in function call request:

worker:  {"ethereum_url":"http://127.0.0.1:3000/eth-mainnet.g.alchemy.com/v2/***","starknet_url":"http://127.0.0.1:3000/starknet-mainnet.g.alchemy.com/starknet/version/rpc/v0_7/***"}
beerus: config ready
beerus: client ready
Beerus instance created
worker:  {"execute":{"calldata":[],"contract_address":"0x49d36570d4e46f48e99674bd3fcc84644ddd6b96f7c741b1562b82f9e004dc7","entry_point_selector":"0x361458367e696363fbcc70777d07ebbd2394e89fd0adcaf147faccd1d294d60"},"id":1}
call to get_block_number completed in 0 ms
call to get_block_by_number completed in 0 ms
call to stateBlockNumber completed in 1961 ms
call to stateBlockHash completed in 3846 ms
call to stateRoot completed in 5890 ms
beerus: execute: state ready
beerus: execute: request ready
call to starknet_getClassHashAt completed in 461 ms
call to starknet_getClass completed in 678 ms
call to starknet_getStorageAt completed in 156 ms
call to pathfinder_getProof completed in 157 ms
beerus: execute: [Felt("0x4574686572")]

[ICavlek]

I have two questions based on observation.

1. Did you deliberately place some of the let now = Instant::now(); inside the #[cfg(target_arch = "wasm32")] scope? Because it seems to me that at the end of the scope, these values are destroyed and the 'start' time is the one used at the top of the function.
2. Is there a wasm32 compilation issue that you are constantly redefining now instead of declaring them as mut?

[sergey-melnychuk]

Did you deliberately place some of the let now = Instant::now(); inside the #[cfg(target_arch = "wasm32")] scope? Because it seems to me that at the end of the scope, these values are destroyed and the 'start' time is the one used at the top of the function.

In general, yes, when I submit code for review it is almost always me deliberately doing something :)

This PR adds latency logging to be observable in the browser only (through wasm, I should have stated that in the PR description probably). So in a non-wasm context we don't need latency measurement (at least at this point), that is the reason why all the relevant code is put under #[cfg(target_arch = "wasm32")] including let now = Instant::now(); before every section of code which execution latency we're interested in.

Updated the PR description to reflect that.

Is there a wasm32 compilation issue that you are constantly redefining now instead of declaring them as mut?

No, there is no compilation issue, just logical separation of latency measurement sections.
Why there needs to be a compilation issue to do that?
What is the problem with redefining now?
What benefits are there in making them mutable?

[sergey-melnychuk]

Did you deliberately place some of the let now = Instant::now(); inside the #[cfg(target_arch = "wasm32")] scope? Because it seems to me that at the end of the scope, these values are destroyed and the 'start' time is the one used at the top of the function.

In general, yes, when I submit code for review it is almost always me deliberately doing something :)

This PR adds latency logging to be observable in the browser only (through wasm, I should have stated that in the PR description probably). So in a non-wasm context we don't need latency measurement (at least at this point), that is the reason why all the relevant code is put under #[cfg(target_arch = "wasm32")] including let now = Instant::now(); before every section of code which execution latency we're interested in.

Updated the PR description to reflect that.

Is there a wasm32 compilation issue that you are constantly redefining now instead of declaring them as mut?

No, there is no compilation issue, just logical separation of latency measurement sections. Why there needs to be a compilation issue to do that? What is the problem with redefining now? What benefits are there in making them mutable?

Good catch @ICavlek , thank you!
It still feels funny (and stupid) to admit such a silly mistake I've made: for some reason my brain totally ignored scopes when they were behind #cfg and even clippy warnings weren't enough to overcome my ignorance!

[ICavlek]

LGTM :)