feat(runtime): debug log host function call except gas

[ailisp]

This fix the problem in #5062 by not logging gas function call. Logging gas was a intention choice because i thought it would be helpful to stat its use but betanet deployment has shown it slowdown the node significantly.

Test Plan

same as #5018, this time the output doesn't have gas:

Oct 25 16:55:57.767  INFO stats: Server listening at ed25519:[email protected]:24567
Oct 25 16:56:01.702 DEBUG input: host-function: enter
Oct 25 16:56:01.702 DEBUG input: host-function: close time.busy=225µs time.idle=29.7µs
Oct 25 16:56:01.702 DEBUG register_len: host-function: enter
Oct 25 16:56:01.702 DEBUG register_len: host-function: close time.busy=118µs time.idle=20.2µs
Oct 25 16:56:01.702 DEBUG read_register: host-function: enter
Oct 25 16:56:01.702 DEBUG read_register: host-function: close time.busy=117µs time.idle=28.8µs
Oct 25 16:56:01.703 DEBUG storage_read: host-function: enter
Oct 25 16:56:01.703 DEBUG storage_read: host-function: close time.busy=330µs time.idle=12.9µs
Oct 25 16:56:01.703 DEBUG register_len: host-function: enter
Oct 25 16:56:01.703 DEBUG register_len: host-function: close time.busy=60.5µs time.idle=11.1µs
Oct 25 16:56:01.703 DEBUG read_register: host-function: enter
Oct 25 16:56:01.703 DEBUG read_register: host-function: close time.busy=72.8µs time.idle=11.1µs
Oct 25 16:56:01.704 DEBUG signer_account_id: host-function: enter
Oct 25 16:56:01.704 DEBUG signer_account_id: host-function: close time.busy=66.7µs time.idle=11.5µs
Oct 25 16:56:01.704 DEBUG register_len: host-function: enter
Oct 25 16:56:01.704 DEBUG register_len: host-function: close time.busy=61.3µs time.idle=10.9µs
Oct 25 16:56:01.704 DEBUG read_register: host-function: enter
Oct 25 16:56:01.704 DEBUG read_register: host-function: close time.busy=72.0µs time.idle=13.8µs
Oct 25 16:56:01.704 DEBUG log_utf8: host-function: enter
Oct 25 16:56:01.704 DEBUG log_utf8: host-function: close time.busy=74.5µs time.idle=11.5µs
Oct 25 16:56:01.704 DEBUG storage_write: host-function: enter
Oct 25 16:56:01.704 DEBUG storage_write: host-function: close time.busy=190µs time.idle=12.2µs
Oct 25 16:56:07.820  INFO stats: #    3339 332KuomX4nwiREdZwRLA63uekeWLnfszv6UtGctn8Tgf V/1  0/0/40 peers ⬇ 0 B/s ⬆ 0 B/s 1.60 bps 543.20 Ggas/s CPU: 0%, Mem: 0 B  

Also @mina86 is there a way to test performance as betanet node before merge it to master?

[ailisp]

@matklad a rust question: I'd like to check in compile-time that stringify!($func) is "gas" or simply $func is token gas. Lookup and it seems only possible in rust function-like macro. And since wrapped_import! has been written as declarative macro, it takes a lot work to turn it to function-like macro just for this.
Currently the span check is a run-time if, if it's a problem to the release, we can limit the statically compiled max tracing level to info: https://tracing.rs/tracing/level_filters/index.html#compile-time-filters.
Is there a better way to write?

[matklad]

Is there a better way to write?

I'd write it like this

const IS_GAS: bool = str_eq(stringify!($func), "gas");
if IS_GAS {} else {}

where str_eq is defined as follows:

https://play.rust-lang.org/?version=stable&mode=debug&edition=2021&gist=668cfc458a980d563ce7fca863182f26

I would expect both to result in the same output in practice today, but I like const IS_GAS: bool soluction because it guarantees that the check is compile-time evaluatable, so we can refactor without fear.

[bowenwang1996]

but betanet deployment has shown it slowdown the node significantly.

Just to be clear, it broke the canary nodes on testnet. You can try running a node on testnet to see if it can keep up with the network.

[mina86]

Also @mina86 is there a way to test performance as betanet node before merge it to master?

There is mocknet load test that @nikurt is working on. I’m not sure whether it would caught the issue.

[ailisp]

@mina86 Thanks. I've followed Bowen's idea on run a node on testnet. I did so by go to a gcloud instance, compile a release neard, init with --download-genesis and --download-config, and run. It's run for more than 12 hours but still Downloading headers, 29.21%, and according to log it takes 20-30s to download 0.01%. Is this normal? Is there a faster way to get the state to start a node?

[mina86]

I've followed Bowen's idea on run a node on testnet. I did so by go to a gcloud instance, compile a release neard, init with --download-genesis and --download-config, and run. It's run for more than 12 hours but still Downloading headers, 29.21%, and according to log it takes 20-30s to download 0.01%. Is this normal? Is there a faster way to get the state to start a node?

That is my experience is well and I don’t have a solution. Copying the data directory from existing node would be an option, but that would require messing up with production.

[ailisp]

Addressed Aleksey's comment. Still waiting my testnet node to finish downloading headers and see if it can catch up. 69% now.

[ailisp]

@mina86 @matklad finished test by run a testnet node. cpu and memory usage is not higher than master

[matklad]

Wait, this doesn't do what we want it to. This ; immediately drops the span, before the host function is even invoked. We do need to bind it to a temporary variable to make sure it is dropped after $func returns:

                        let _span = if IS_GAS {
                            None
                        } else {
                            Some(tracing::debug_span!(target: "host-function", stringify!($func)).entered())
                        };

[ailisp]

ah yes. Sorry

[ailisp]

Test again on testnet, with correctly set _span the time of certain host functions looks realistic! (and cpu/mem usage still good, as expected)

[mina86]

LGTM