From 3b1024b7db799f995a3b0266c5512aaf1d7f2770 Mon Sep 17 00:00:00 2001 From: Valery Antopol Date: Wed, 9 Aug 2023 04:44:50 +0300 Subject: [PATCH] add more tracing entries --- Cargo.lock | 2 ++ core/src/host_imports/imports.rs | 4 +++- core/src/module/exports.rs | 1 + core/src/module/marine_module.rs | 1 + core/src/module/wit_instance.rs | 1 + crates/fluence-app-service/Cargo.toml | 1 + crates/fluence-app-service/src/service.rs | 6 ++++++ crates/js-backend/src/function.rs | 2 ++ crates/js-backend/src/memory.rs | 1 + crates/js-backend/src/module.rs | 9 +++++---- crates/wasmtime-backend/Cargo.toml | 1 + crates/wasmtime-backend/src/function.rs | 2 ++ crates/wasmtime-backend/src/memory.rs | 1 + crates/wasmtime-backend/src/module.rs | 3 +++ marine-js/src/api.rs | 9 +++++++-- marine-js/src/lib.rs | 10 ++++------ marine/src/marine.rs | 1 + marine/src/module_loading/mod.rs | 1 + 18 files changed, 43 insertions(+), 13 deletions(-) diff --git a/Cargo.lock b/Cargo.lock index 07a0e936..4216187f 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -1271,6 +1271,7 @@ dependencies = [ "serde_derive", "serde_json", "toml 0.5.11", + "tracing", ] [[package]] @@ -2555,6 +2556,7 @@ dependencies = [ "marine-wasm-backend-traits", "multimap", "paste", + "tracing", "wasmer-interface-types-fl 0.26.1", "wasmtime", "wasmtime-wasi", diff --git a/core/src/host_imports/imports.rs b/core/src/host_imports/imports.rs index 5329f9aa..078edab4 100644 --- a/core/src/host_imports/imports.rs +++ b/core/src/host_imports/imports.rs @@ -58,7 +58,7 @@ pub(crate) fn create_host_import_func( func, ) } - +#[tracing::instrument(level = "trace", skip_all)] fn call_host_import( mut caller: ::ImportCallContext<'_>, inputs: &[WValue], @@ -96,6 +96,7 @@ fn call_host_import( lower_outputs::(&mut caller, memory, output) } +#[tracing::instrument(level = "trace", skip_all)] fn lift_inputs( caller: &mut ::ImportCallContext<'_>, memory: ::Memory, @@ -114,6 +115,7 @@ fn lift_inputs( ) } +#[tracing::instrument(level = "trace", skip_all)] fn lower_outputs( caller: &mut ::ImportCallContext<'_>, memory: ::Memory, diff --git a/core/src/module/exports.rs b/core/src/module/exports.rs index 02219de8..7ddb2f43 100644 --- a/core/src/module/exports.rs +++ b/core/src/module/exports.rs @@ -63,6 +63,7 @@ impl wasm::structures::Export for ITExport { &self.outputs } + #[tracing::instrument(level = "trace", skip_all)] fn call(&self, arguments: &[IValue]) -> Result, ()> { (self.function)(arguments) } diff --git a/core/src/module/marine_module.rs b/core/src/module/marine_module.rs index 0df22572..03a93a8b 100644 --- a/core/src/module/marine_module.rs +++ b/core/src/module/marine_module.rs @@ -159,6 +159,7 @@ impl MModule { }) } + #[tracing::instrument(level = "trace", skip_all)] pub(crate) fn call( &mut self, store: &mut ::ContextMut<'_>, diff --git a/core/src/module/wit_instance.rs b/core/src/module/wit_instance.rs index 5e90443a..9a55d6c7 100644 --- a/core/src/module/wit_instance.rs +++ b/core/src/module/wit_instance.rs @@ -52,6 +52,7 @@ pub(super) struct ITInstance { } impl ITInstance { + #[tracing::instrument(level = "trace", skip_all)] pub(super) fn new( wasm_instance: &::Instance, store: &mut ::Store, diff --git a/crates/fluence-app-service/Cargo.toml b/crates/fluence-app-service/Cargo.toml index c7585a21..03f6098c 100644 --- a/crates/fluence-app-service/Cargo.toml +++ b/crates/fluence-app-service/Cargo.toml @@ -18,6 +18,7 @@ serde = "1.0.147" serde_derive = "1.0.147" serde_json = "1.0.89" toml = "0.5.9" +tracing = "0.1.37" [features] raw-module-api = ["marine-runtime/raw-module-api"] diff --git a/crates/fluence-app-service/src/service.rs b/crates/fluence-app-service/src/service.rs index 6577e90e..7163fcb8 100644 --- a/crates/fluence-app-service/src/service.rs +++ b/crates/fluence-app-service/src/service.rs @@ -45,6 +45,7 @@ pub struct AppService { impl AppService { /// Create Service with given modules and service id. + #[tracing::instrument(level = "trace", skip_all)] pub fn new(config: C, service_id: S, envs: HashMap) -> Result where C: TryInto, @@ -76,6 +77,7 @@ impl AppService { } /// Call a specified function of loaded module by its name with arguments in json format. + #[tracing::instrument(level = "trace", skip_all)] pub fn call( &mut self, func_name: impl AsRef, @@ -93,6 +95,7 @@ impl AppService { } /// Call a specified function of loaded module by its name with arguments in IValue format. + #[tracing::instrument(level = "trace", skip_all)] pub fn call_with_ivalues( &mut self, func_name: impl AsRef, @@ -185,6 +188,7 @@ impl AppService { // This API is intended for testing purposes (mostly in Marine REPL) #[cfg(feature = "raw-module-api")] impl AppService { + #[tracing::instrument(level = "trace", skip_all)] pub fn new_with_empty_facade( config: C, service_id: S, @@ -207,6 +211,7 @@ impl AppService { }) } + #[tracing::instrument(level = "trace", skip_all)] pub fn call_module( &mut self, module_name: impl AsRef, @@ -219,6 +224,7 @@ impl AppService { .map_err(Into::into) } + #[tracing::instrument(level = "trace", skip_all)] pub fn load_module(&mut self, name: S, wasm_bytes: &[u8], config: Option) -> Result<()> where S: Into, diff --git a/crates/js-backend/src/function.rs b/crates/js-backend/src/function.rs index aa81f454..cf4cb03a 100644 --- a/crates/js-backend/src/function.rs +++ b/crates/js-backend/src/function.rs @@ -200,6 +200,7 @@ where F: for<'c> Fn(JsImportCallContext, &[WValue]) -> Vec + Sync + Send + 'static, { let func = move |args: &js_sys::Array| -> js_sys::Array { + let _span = tracing::trace_span!("calling import function"); log::debug!( "function produced by JsFunction:::new_with_caller call, signature: {:?}", signature @@ -240,6 +241,7 @@ impl ExportFunction for WasmExportFunction { self.stored_mut(store.as_context_mut()).signature.clone() } + #[tracing::instrument(level = "trace", skip_all)] fn call( &self, store: &mut impl AsContextMut, diff --git a/crates/js-backend/src/memory.rs b/crates/js-backend/src/memory.rs index 5724f3a3..acd925ae 100644 --- a/crates/js-backend/src/memory.rs +++ b/crates/js-backend/src/memory.rs @@ -121,6 +121,7 @@ impl it_memory_traits::MemoryReadable> for result } + #[tracing::instrument(level = "trace", skip_all)] fn read_vec( &self, _store: &mut as it_memory_traits::Store>::ActualStore< diff --git a/crates/js-backend/src/module.rs b/crates/js-backend/src/module.rs index d06585d1..d93b233c 100644 --- a/crates/js-backend/src/module.rs +++ b/crates/js-backend/src/module.rs @@ -44,9 +44,9 @@ impl Module for JsModule { WebAssembly::Module::new(&data_obj).map_err(|e| { log::debug!("Module::new failed: {:?}", e); ModuleCreationError::FailedToCompileWasm(anyhow!(format!( - "error compiling module: {:?}", - e - ))) + "error compiling module: {:?}", + e + ))) })? }; @@ -78,7 +78,8 @@ impl Module for JsModule { let imports_object = imports.build_import_object(store.as_context(), &self.inner); let instance = { - let span = tracing::span!(tracing::Level::TRACE, "WebAssembly::Instance::new").entered(); + let span = + tracing::span!(tracing::Level::TRACE, "WebAssembly::Instance::new").entered(); WebAssembly::Instance::new(&self.inner, &imports_object) .map_err(|e| InstantiationError::Other(anyhow!("failed to instantiate: {:?}", e)))? }; diff --git a/crates/wasmtime-backend/Cargo.toml b/crates/wasmtime-backend/Cargo.toml index 41d634e9..a5f6b52e 100644 --- a/crates/wasmtime-backend/Cargo.toml +++ b/crates/wasmtime-backend/Cargo.toml @@ -18,3 +18,4 @@ multimap = "0.8.3" paste = "1.0.13" anyhow = "1.0.71" log = "0.4.19" +tracing = "0.1.37" \ No newline at end of file diff --git a/crates/wasmtime-backend/src/function.rs b/crates/wasmtime-backend/src/function.rs index 9294a500..e61f77b0 100644 --- a/crates/wasmtime-backend/src/function.rs +++ b/crates/wasmtime-backend/src/function.rs @@ -74,6 +74,7 @@ impl HostFunction for WasmtimeFunction { args: &[wasmtime::Val], results_out: &mut [wasmtime::Val]| -> Result<(), anyhow::Error> { + let _span = tracing::trace_span!("calling import function").entered(); let caller = WasmtimeImportCallContext { inner: caller }; let args = process_func_args(args).map_err(|e| anyhow!(e))?; let results = func(caller, &args); @@ -103,6 +104,7 @@ impl ExportFunction for WasmtimeFunction { fn_ty_to_sig(&ty) } + #[tracing::instrument(level = "trace", skip_all)] fn call<'c>( &self, store: &mut impl AsContextMut, diff --git a/crates/wasmtime-backend/src/memory.rs b/crates/wasmtime-backend/src/memory.rs index afe66338..e26ff6e8 100644 --- a/crates/wasmtime-backend/src/memory.rs +++ b/crates/wasmtime-backend/src/memory.rs @@ -76,6 +76,7 @@ impl it_memory_traits::MemoryReadable, offset: u32, size: u32) -> Vec { let mut value = vec![0u8; size as usize]; self.memory diff --git a/crates/wasmtime-backend/src/module.rs b/crates/wasmtime-backend/src/module.rs index dd2818d9..683cf203 100644 --- a/crates/wasmtime-backend/src/module.rs +++ b/crates/wasmtime-backend/src/module.rs @@ -31,6 +31,7 @@ pub struct WasmtimeModule { } impl Module for WasmtimeModule { + #[tracing::instrument(level = "trace", skip_all)] fn new(store: &mut WasmtimeStore, wasm: &[u8]) -> ModuleCreationResult { let module = wasmtime::Module::new(store.inner.engine(), wasm) .map_err(ModuleCreationError::FailedToCompileWasm)?; @@ -44,6 +45,7 @@ impl Module for WasmtimeModule { }) } + #[tracing::instrument(level = "trace", skip_all)] fn custom_sections(&self, name: &str) -> &[Vec] { self.custom_sections .get_vec(name) @@ -51,6 +53,7 @@ impl Module for WasmtimeModule { .unwrap_or_default() } + #[tracing::instrument(level = "trace", skip_all)] fn instantiate( &self, store: &mut WasmtimeStore, diff --git a/marine-js/src/api.rs b/marine-js/src/api.rs index 830e5a4a..12ff2f3a 100644 --- a/marine-js/src/api.rs +++ b/marine-js/src/api.rs @@ -150,7 +150,7 @@ pub fn register_module( modules: js_sys::Object, log_fn: js_sys::Function, ) -> Result<(), JsError> { - let _span = tracing::trace_span!( "register_module").entered(); + let _span = tracing::trace_span!("register_module").entered(); let mut config: ApiServiceConfig = serde_wasm_bindgen::from_value(config)?; let modules = extract_modules(modules)?; @@ -204,7 +204,12 @@ pub fn call_module( args: &str, call_parameters: JsValue, ) -> Result { - let _span = tracing::trace_span!( "call_module", module_name = module_name, function_name = function_name).entered(); + let _span = tracing::trace_span!( + "call_module", + module_name = module_name, + function_name = function_name + ) + .entered(); let call_parameters = serde_wasm_bindgen::from_value(call_parameters)?; MARINE.with(|marine| { diff --git a/marine-js/src/lib.rs b/marine-js/src/lib.rs index 2d430c79..f8a1392a 100644 --- a/marine-js/src/lib.rs +++ b/marine-js/src/lib.rs @@ -31,15 +31,13 @@ fn main() { init_tracing(); } - #[allow(dead_code)] pub fn init_tracing() { let config = tracing_wasm::WASMLayerConfigBuilder::new() - .set_max_level(tracing::Level::TRACE) - .set_report_logs_in_timings(true) - .set_console_config(tracing_wasm::ConsoleConfig::ReportWithoutConsoleColor) - .build(); + .set_max_level(tracing::Level::TRACE) + .set_report_logs_in_timings(true) + .set_console_config(tracing_wasm::ConsoleConfig::ReportWithoutConsoleColor) + .build(); tracing_wasm::set_as_global_default_with_config(config) } - diff --git a/marine/src/marine.rs b/marine/src/marine.rs index e21bc32c..8a58cf21 100644 --- a/marine/src/marine.rs +++ b/marine/src/marine.rs @@ -268,6 +268,7 @@ impl Marine { // This API is intended for testing purposes (mostly in Marine REPL) #[cfg(feature = "raw-module-api")] impl Marine { + #[tracing::instrument(level = "trace", skip_all)] pub fn load_module( &mut self, name: S, diff --git a/marine/src/module_loading/mod.rs b/marine/src/module_loading/mod.rs index 5754369f..25986edb 100644 --- a/marine/src/module_loading/mod.rs +++ b/marine/src/module_loading/mod.rs @@ -21,6 +21,7 @@ use std::collections::HashMap; use std::path::PathBuf; /// Loads modules from a directory at a given path. Non-recursive, ignores subdirectories. +#[tracing::instrument(level = "trace", skip_all)] pub(crate) fn load_modules_from_fs( modules: &HashMap, ) -> MarineResult>> {