From 05035d40a3416887a3102168c1d14b33e852af94 Mon Sep 17 00:00:00 2001 From: Bo Yao Date: Wed, 3 Nov 2021 22:00:32 +0800 Subject: [PATCH] feat(runtime): debug log host function call except gas (#5076) MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit 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:5V9BRNjjF7FvHBMH4QRWyeQHnNVhGj7rxnHVTbVmt2Wj@0.0.0.0: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? --- runtime/near-vm-runner/src/imports.rs | 37 +++++++++++++++++++++++++++ 1 file changed, 37 insertions(+) diff --git a/runtime/near-vm-runner/src/imports.rs b/runtime/near-vm-runner/src/imports.rs index 1f53b8fd7ff..ab922f150de 100644 --- a/runtime/near-vm-runner/src/imports.rs +++ b/runtime/near-vm-runner/src/imports.rs @@ -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 @@ -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 = ::std::result::Result; $( #[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, )* ) } @@ -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 = ::std::result::Result; $( #[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, )* ) } @@ -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); @@ -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()