Skip to content

Commit

Permalink
feat(runtime): debug log host function call except gas (#5076)
Browse files Browse the repository at this point in the history 
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?
  • Loading branch information
@ailisp @olonho
ailisp authored and olonho committed Nov 4, 2021
1 parent e35febd commit 05035d4
Showing 1 changed file with 37 additions and 0 deletions.
37 changes: 37 additions & 0 deletions runtime/near-vm-runner/src/imports.rs
View file
Original file line number Diff line number Diff line change
Expand Up @@ -18,6 +18,22 @@ pub struct NearWasmerEnv {
pub logic: ImportReference,
}

const fn str_eq(s1: &str, s2: &str) -> bool {
let s1 = s1.as_bytes();
let s2 = s2.as_bytes();
if s1.len() != s2.len() {
return false;
}
let mut i = 0;
while i < s1.len() {
if s1[i] != s2[i] {
return false;
}
i += 1;
}
true
}

// Wasm has only i32/i64 types, so Wasmtime 0.17 only accepts
// external functions taking i32/i64 type.
// Remove, once using version with https://github.com/bytecodealliance/wasmtime/issues/1829
Expand All @@ -41,11 +57,18 @@ macro_rules! wrapped_imports {
pub mod wasmer_ext {
use near_vm_logic::VMLogic;
use wasmer_runtime::Ctx;
use crate::imports::str_eq;
type VMResult<T> = ::std::result::Result<T, near_vm_logic::VMLogicError>;
$(
#[allow(unused_parens)]
$(#[cfg(feature = $feature_name)])*
pub fn $func( ctx: &mut Ctx, $( $arg_name: $arg_type ),* ) -> VMResult<($( $returns ),*)> {
const IS_GAS: bool = str_eq(stringify!($func), "gas");
let _span = if IS_GAS {
None
} else {
Some(tracing::debug_span!(target: "host-function", stringify!($func)).entered())
};
let logic: &mut VMLogic<'_> = unsafe { &mut *(ctx.data as *mut VMLogic<'_>) };
logic.$func( $( $arg_name, )* )
}
Expand All @@ -56,12 +79,19 @@ macro_rules! wrapped_imports {
pub mod wasmer2_ext {
use near_vm_logic::VMLogic;
use crate::imports::NearWasmerEnv;
use crate::imports::str_eq;

type VMResult<T> = ::std::result::Result<T, near_vm_logic::VMLogicError>;
$(
#[allow(unused_parens)]
$(#[cfg(feature = $feature_name)])*
pub fn $func(env: &NearWasmerEnv, $( $arg_name: $arg_type ),* ) -> VMResult<($( $returns ),*)> {
const IS_GAS: bool = str_eq(stringify!($func), "gas");
let _span = if IS_GAS {
None
} else {
Some(tracing::debug_span!(target: "host-function", stringify!($func)).entered())
};
let logic: &mut VMLogic = unsafe { &mut *(env.logic.0 as *mut VMLogic<'_>) };
logic.$func( $( $arg_name, )* )
}
Expand All @@ -74,6 +104,7 @@ macro_rules! wrapped_imports {
use std::ffi::c_void;
use std::cell::{RefCell, UnsafeCell};
use wasmtime::Trap;
use crate::imports::str_eq;

thread_local! {
pub static CALLER_CONTEXT: UnsafeCell<*mut c_void> = UnsafeCell::new(0 as *mut c_void);
Expand All @@ -85,6 +116,12 @@ macro_rules! wrapped_imports {
#[allow(unused_parens)]
#[cfg(all(feature = "wasmtime_vm" $(, feature = $feature_name)*))]
pub fn $func( $( $arg_name: rust2wasm!($arg_type) ),* ) -> VMResult<($( rust2wasm!($returns)),*)> {
const IS_GAS: bool = str_eq(stringify!($func), "gas");
let _span =if IS_GAS {
None
} else {
Some(tracing::debug_span!(target: "host-function", stringify!($func)).entered())
};
let data = CALLER_CONTEXT.with(|caller_context| {
unsafe {
*caller_context.get()
Expand Down

0 comments on commit 05035d4

Please sign in to comment.