Skip to content

Commit

Permalink
fix(logging): Add "near_vm" target to near-vm logging (#9397)
Browse files Browse the repository at this point in the history
Near VM logging is rather verbose, but controlling it requires setting logging verbosity of many different implicit targets.
With this change all of `near_vm` logging can be controlled with a single target.

Before:
```
Aug 08 13:10:57 nikurt-dump neard[1295836]: 2023-08-08T13:10:57.647968Z  INFO do_apply_chunks{block_height=98346897 block_hash=7jBX38Y6UGkBCnMzrGRqsx2cxbZjNyzBJi3JV66vE3uK}:new_chunk{shard_id=0}:process_state_update:apply{num_transactions=2}:process_receipt{receipt_id=3c3oBDaQCthsaxhbw5NR1ytAC4NgYANubH5KSVCDnExA predecessor=app.nearcrowd.near receiver=app.nearcrowd.near id=3c3oBDaQCthsaxhbw5NR1ytAC4NgYANubH5KSVCDnExA}:run{code.len=484251 method_name=finalize_task vm_kind=NearVm current_protocol_version=62}:NearVM::compile_and_load:NearVM::read_from_cache:link_module: near_vm_engine::universal::link: enter
Aug 08 13:10:57 nikurt-dump neard[1295836]: 2023-08-08T13:10:57.648494Z  INFO do_apply_chunks{block_height=98346897 block_hash=7jBX38Y6UGkBCnMzrGRqsx2cxbZjNyzBJi3JV66vE3uK}:new_chunk{shard_id=0}:process_state_update:apply{num_transactions=2}:process_receipt{receipt_id=3c3oBDaQCthsaxhbw5NR1ytAC4NgYANubH5KSVCDnExA predecessor=app.nearcrowd.near receiver=app.nearcrowd.near id=3c3oBDaQCthsaxhbw5NR1ytAC4NgYANubH5KSVCDnExA}:run{code.len=484251 method_name=finalize_task vm_kind=NearVm current_protocol_version=62}:NearVM::compile_and_load:NearVM::read_from_cache:link_module: near_vm_engine::universal::link: close time.busy=525µs time.idle=7.86µs
Aug 08 13:10:57 nikurt-dump neard[1295836]: 2023-08-08T13:10:57.675082Z  INFO do_apply_chunks{block_height=98346897 block_hash=7jBX38Y6UGkBCnMzrGRqsx2cxbZjNyzBJi3JV66vE3uK}:new_chunk{shard_id=3}:process_state_update:apply{num_transactions=1}:process_receipt{receipt_id=4EDkP4qS6Q2GJGFgYGqVDoTeFP96eH8tA7u7yaqVxctk predecessor=p4.spimm.near receiver=v2_0_2.perp.spin-fi.near id=4EDkP4qS6Q2GJGFgYGqVDoTeFP96eH8tA7u7yaqVxctk}:run{code.len=2777209 method_name=batch_ops vm_kind=NearVm current_protocol_version=62}:NearVM::compile_and_load:NearVM::read_from_cache:link_module: near_vm_engine::universal::link: enter
```

After:
```
Aug 08 13:05:45 nikurt-dump neard[130008]: 2023-08-08T13:05:42.955565Z  INFO do_apply_chunks{block_height=134354991 block_hash=6peTfFzPBa9JHerVZEaaNFMenrL8fqhaNXycNpwv523v}:new_chunk{shard_id=1}:process_state_update:apply{num_transactions=0}:process_receipt{receipt_id=5kG2gYSYNEdyZjtsD8JQC3dLUhHiqZnxGr11Jj53TZqP predecessor=relay.aurora receiver=aurora id=5kG2gYSYNEdyZjtsD8JQC3dLUhHiqZnxGr11Jj53TZqP}:run{code.len=1060370 method_name=submit vm_kind=NearVm current_protocol_version=62}:NearVM::compile_and_load:NearVM::read_from_cache:link_module: near_vm: close time.busy=887µs time.idle=8.13µs
Aug 08 13:05:45 nikurt-dump neard[130008]: 2023-08-08T13:05:42.955868Z  INFO do_apply_chunks{block_height=134354991 block_hash=6peTfFzPBa9JHerVZEaaNFMenrL8fqhaNXycNpwv523v}:new_chunk{shard_id=0}:process_state_update:apply{num_transactions=0}:process_receipt{receipt_id=EsKMrLV9cG9LeLc9osHvMJKDkLKJepyifBAWZPCHghif predecessor=operator-manager.orderly-qa.testnet receiver=asset-manager.orderly-qa.testnet id=EsKMrLV9cG9LeLc9osHvMJKDkLKJepyifBAWZPCHghif}:run{code.len=3211876 method_name=operator_execute_action vm_kind=NearVm current_protocol_version=62}:NearVM::compile_and_load:NearVM::read_from_cache:link_module: near_vm: enter
Aug 08 13:05:45 nikurt-dump neard[130008]: 2023-08-08T13:05:42.957634Z  INFO do_apply_chunks{block_height=134354991 block_hash=6peTfFzPBa9JHerVZEaaNFMenrL8fqhaNXycNpwv523v}:new_chunk{shard_id=0}:process_state_update:apply{num_transactions=0}:process_receipt{receipt_id=EsKMrLV9cG9LeLc9osHvMJKDkLKJepyifBAWZPCHghif predecessor=operator-manager.orderly-qa.testnet receiver=asset-manager.orderly-qa.testnet id=EsKMrLV9cG9LeLc9osHvMJKDkLKJepyifBAWZPCHghif}:run{code.len=3211876 method_name=operator_execute_action vm_kind=NearVm current_protocol_version=62}:NearVM::compile_and_load:NearVM::read_from_cache:link_module: near_vm: close time.busy=1.76ms time.idle=6.62µs

```
  • Loading branch information
nikurt authored Aug 9, 2023
1 parent e467916 commit fa75265
Show file tree
Hide file tree
Showing 12 changed files with 28 additions and 26 deletions.
12 changes: 6 additions & 6 deletions runtime/near-vm/compiler-singlepass/src/codegen_x64.rs
Original file line number Diff line number Diff line change
Expand Up @@ -1695,7 +1695,7 @@ impl<'a> FuncGen<'a> {
});
}

#[tracing::instrument(skip_all)]
#[tracing::instrument(target = "near_vm", skip_all)]
pub(crate) fn new(
assembler: &'a mut Assembler,
module: &'a ModuleInfo,
Expand Down Expand Up @@ -1802,7 +1802,7 @@ impl<'a> FuncGen<'a> {
None
}

#[tracing::instrument(skip(self))]
#[tracing::instrument(target = "near_vm", skip(self))]
pub(crate) fn feed_operator(&mut self, op: Operator) -> Result<(), CodegenError> {
assert!(self.fp_stack.len() <= self.value_stack.len());

Expand Down Expand Up @@ -7663,7 +7663,7 @@ impl<'a> FuncGen<'a> {
Ok(())
}

#[tracing::instrument(skip_all)]
#[tracing::instrument(target = "near_vm", skip_all)]
pub(crate) fn finalize(mut self, data: &FunctionBodyData) -> CompiledFunction {
debug_assert!(
self.gas_iter.next().is_none(),
Expand Down Expand Up @@ -7776,7 +7776,7 @@ fn sort_call_movs(movs: &mut [(Location, GPR)]) {
}

// Standard entry trampoline.
#[tracing::instrument]
#[tracing::instrument(target = "near_vm")]
pub(crate) fn gen_std_trampoline(
sig: &FunctionType,
calling_convention: CallingConvention,
Expand Down Expand Up @@ -7869,7 +7869,7 @@ pub(crate) fn gen_std_trampoline(
}

/// Generates dynamic import function call trampoline for a function type.
#[tracing::instrument(skip(vmoffsets))]
#[tracing::instrument(target = "near_vm", skip(vmoffsets))]
pub(crate) fn gen_std_dynamic_import_trampoline(
vmoffsets: &VMOffsets,
sig: &FunctionType,
Expand Down Expand Up @@ -7987,7 +7987,7 @@ pub(crate) fn gen_std_dynamic_import_trampoline(
}

// Singlepass calls import functions through a trampoline.
#[tracing::instrument(skip(vmoffsets))]
#[tracing::instrument(target = "near_vm", skip(vmoffsets))]
pub(crate) fn gen_import_call_trampoline(
vmoffsets: &VMOffsets,
index: FunctionIndex,
Expand Down
17 changes: 9 additions & 8 deletions runtime/near-vm/compiler-singlepass/src/compiler.rs
Original file line number Diff line number Diff line change
Expand Up @@ -41,7 +41,7 @@ impl SinglepassCompiler {
impl Compiler for SinglepassCompiler {
/// Compile the module using Singlepass, producing a compilation result with
/// associated relocations.
#[tracing::instrument(skip_all)]
#[tracing::instrument(target = "near_vm", skip_all)]
fn compile_module(
&self,
target: &Target,
Expand Down Expand Up @@ -87,7 +87,7 @@ impl Compiler for SinglepassCompiler {
};
let import_idxs = 0..module.import_counts.functions as usize;
let import_trampolines: PrimaryMap<SectionIndex, _> =
tracing::info_span!("import_trampolines", n_imports = import_idxs.len()).in_scope(
tracing::info_span!(target: "near_vm", "import_trampolines", n_imports = import_idxs.len()).in_scope(
|| {
import_idxs
.into_par_iter()
Expand All @@ -111,7 +111,7 @@ impl Compiler for SinglepassCompiler {
.collect::<Vec<(LocalFunctionIndex, &FunctionBodyData<'_>)>>()
.into_par_iter()
.map_init(make_assembler, |assembler, (i, input)| {
tracing::info_span!("function", i = i.index()).in_scope(|| {
tracing::info_span!(target: "near_vm", "function", i = i.index()).in_scope(|| {
let reader =
near_vm_compiler::FunctionReader::new(input.module_offset, input.data);
let stack_init_gas_cost = tunables
Expand Down Expand Up @@ -154,8 +154,9 @@ impl Compiler for SinglepassCompiler {
let mut operator_reader =
reader.get_operators_reader()?.into_iter_with_offsets();
while generator.has_control_frames() {
let (op, pos) = tracing::info_span!("parsing-next-operator")
.in_scope(|| operator_reader.next().unwrap())?;
let (op, pos) =
tracing::info_span!(target: "near_vm", "parsing-next-operator")
.in_scope(|| operator_reader.next().unwrap())?;
generator.set_srcloc(pos as u32);
generator.feed_operator(op).map_err(to_compile_error)?;
}
Expand All @@ -168,7 +169,7 @@ impl Compiler for SinglepassCompiler {
.collect::<PrimaryMap<LocalFunctionIndex, CompiledFunction>>();

let function_call_trampolines =
tracing::info_span!("function_call_trampolines").in_scope(|| {
tracing::info_span!(target: "near_vm", "function_call_trampolines").in_scope(|| {
module
.signatures
.values()
Expand All @@ -182,8 +183,8 @@ impl Compiler for SinglepassCompiler {
.collect::<PrimaryMap<_, _>>()
});

let dynamic_function_trampolines = tracing::info_span!("dynamic_function_trampolines")
.in_scope(|| {
let dynamic_function_trampolines =
tracing::info_span!(target: "near_vm", "dynamic_function_trampolines").in_scope(|| {
module
.imported_function_types()
.collect::<Vec<_>>()
Expand Down
2 changes: 1 addition & 1 deletion runtime/near-vm/compiler/src/translator/environ.rs
Original file line number Diff line number Diff line change
Expand Up @@ -59,7 +59,7 @@ impl<'data> ModuleEnvironment<'data> {

/// Translate a wasm module using this environment. This consumes the
/// `ModuleEnvironment` and produces a `ModuleInfoTranslation`.
#[tracing::instrument(skip_all)]
#[tracing::instrument(target = "near_vm", skip_all)]
pub fn translate(mut self, data: &'data [u8]) -> WasmResult<ModuleEnvironment<'data>> {
assert!(self.module_translation_state.is_none());
let module_translation_state = translate_module(data, &mut self)?;
Expand Down
2 changes: 1 addition & 1 deletion runtime/near-vm/compiler/src/translator/module.rs
Original file line number Diff line number Diff line change
Expand Up @@ -15,7 +15,7 @@ use wasmparser::{NameSectionReader, Parser, Payload};

/// Translate a sequence of bytes forming a valid Wasm binary into a
/// parsed ModuleInfo `ModuleTranslationState`.
#[tracing::instrument(skip_all)]
#[tracing::instrument(target = "near_vm", skip_all)]
pub fn translate_module<'data>(
data: &'data [u8],
environ: &mut ModuleEnvironment<'data>,
Expand Down
2 changes: 1 addition & 1 deletion runtime/near-vm/compiler/src/translator/state.rs
Original file line number Diff line number Diff line change
Expand Up @@ -35,7 +35,7 @@ impl ModuleTranslationState {
}

/// Build map of imported functions names for intrinsification.
#[tracing::instrument(skip_all)]
#[tracing::instrument(target = "near_vm", skip_all)]
pub fn build_import_map(&mut self, module: &ModuleInfo) {
for key in module.imports.keys() {
let value = &module.imports[key];
Expand Down
1 change: 1 addition & 0 deletions runtime/near-vm/engine/src/universal/code_memory.rs
Original file line number Diff line number Diff line change
Expand Up @@ -228,6 +228,7 @@ impl Drop for CodeMemory {
unsafe {
if let Err(e) = mm::munmap(self.map.cast(), self.size) {
tracing::error!(
target: "near_vm",
message="could not unmap mapping",
map=?self.map, size=self.size, error=%e
);
Expand Down
6 changes: 3 additions & 3 deletions runtime/near-vm/engine/src/universal/engine.rs
Original file line number Diff line number Diff line change
Expand Up @@ -91,7 +91,7 @@ impl UniversalEngine {
}

/// Compile a WebAssembly binary
#[tracing::instrument(skip_all)]
#[tracing::instrument(target = "near_vm", skip_all)]
pub fn compile_universal(
&self,
binary: &[u8],
Expand Down Expand Up @@ -181,7 +181,7 @@ impl UniversalEngine {
}

/// Load a [`UniversalExecutable`](crate::UniversalExecutable) with this engine.
#[tracing::instrument(skip_all)]
#[tracing::instrument(target = "near_vm", skip_all)]
pub fn load_universal_executable(
&self,
executable: &UniversalExecutable,
Expand Down Expand Up @@ -470,7 +470,7 @@ impl UniversalEngine {
}

/// Validates a WebAssembly module
#[tracing::instrument(skip_all)]
#[tracing::instrument(target = "near_vm", skip_all)]
pub fn validate(&self, binary: &[u8]) -> Result<(), CompileError> {
self.inner().validate(binary)
}
Expand Down
2 changes: 1 addition & 1 deletion runtime/near-vm/engine/src/universal/link.rs
Original file line number Diff line number Diff line change
Expand Up @@ -165,7 +165,7 @@ fn apply_relocation(

/// Links a module, patching the allocated functions with the
/// required relocations and jump tables.
#[tracing::instrument(skip_all)]
#[tracing::instrument(target = "near_vm", skip_all)]
pub fn link_module(
allocated_functions: &PrimaryMap<LocalFunctionIndex, VMLocalFunction>,
jt_offsets: impl Fn(LocalFunctionIndex, JumpTable) -> near_vm_compiler::CodeOffset,
Expand Down
2 changes: 1 addition & 1 deletion runtime/near-vm/test-api/src/sys/instance.rs
Original file line number Diff line number Diff line change
Expand Up @@ -102,7 +102,7 @@ impl Instance {
/// Those are, as defined by the spec:
/// * Link errors that happen when plugging the imports into the instance
/// * Runtime errors that happen when running the module `start` function.
#[tracing::instrument(skip_all)]
#[tracing::instrument(target = "near_vm", skip_all)]
pub fn new_with_config(
module: &Module,
config: InstanceConfig,
Expand Down
4 changes: 2 additions & 2 deletions runtime/near-vm/test-api/src/sys/module.rs
Original file line number Diff line number Diff line change
Expand Up @@ -96,7 +96,7 @@ impl Module {
/// # }
/// ```
#[allow(unreachable_code)]
#[tracing::instrument(skip_all)]
#[tracing::instrument(target = "near_vm", skip_all)]
pub fn new(store: &Store, bytes: impl AsRef<[u8]>) -> Result<Self, CompileError> {
#[cfg(feature = "wat")]
let bytes = wat::parse_bytes(bytes.as_ref()).map_err(|e| {
Expand All @@ -111,7 +111,7 @@ impl Module {
/// Opposed to [`Module::new`], this function is not compatible with
/// the WebAssembly text format (if the "wat" feature is enabled for
/// this crate).
#[tracing::instrument(skip_all)]
#[tracing::instrument(target = "near_vm", skip_all)]
pub(crate) fn from_binary(store: &Store, binary: &[u8]) -> Result<Self, CompileError> {
let engine = store.engine();
engine.validate(binary)?;
Expand Down
2 changes: 1 addition & 1 deletion runtime/near-vm/vm/src/instance/mod.rs
Original file line number Diff line number Diff line change
Expand Up @@ -1146,7 +1146,7 @@ impl InstanceHandle {
/// visible to code in `near_vm_vm`, so it's the caller's responsibility to ensure these
/// functions are called with the correct type.
/// - `instance_ptr` must point to a valid `near_vm_test_api::Instance`.
#[tracing::instrument(skip_all)]
#[tracing::instrument(target = "near_vm", skip_all)]
pub unsafe fn initialize_host_envs<Err: Sized>(
handle: &std::sync::Mutex<InstanceHandle>,
instance_ptr: *const ffi::c_void,
Expand Down
2 changes: 1 addition & 1 deletion runtime/near-vm/vm/src/vmoffsets.rs
Original file line number Diff line number Diff line change
Expand Up @@ -116,7 +116,7 @@ impl VMOffsets {
}

/// Add imports and locals from the provided ModuleInfo.
#[tracing::instrument(skip_all)]
#[tracing::instrument(target = "near_vm", skip_all)]
pub fn with_module_info(mut self, module: &ModuleInfo) -> Self {
self.num_imported_functions = module.import_counts.functions;
self.num_imported_tables = module.import_counts.tables;
Expand Down

0 comments on commit fa75265

Please sign in to comment.