From 801d8a3bbe1eec3e8e28c4e19dbbcdfebebff65f Mon Sep 17 00:00:00 2001 From: Graydon Hoare Date: Fri, 14 Jul 2023 21:12:04 -0700 Subject: [PATCH] Add "tracy" feature to enable Tracy profiler, with some basic annotations --- Cargo.lock | 159 +++++++++++++++++- deny.toml | 10 +- soroban-env-host/Cargo.toml | 4 + soroban-env-host/src/auth.rs | 5 + soroban-env-host/src/budget.rs | 11 +- soroban-env-host/src/host.rs | 13 +- soroban-env-host/src/host/comparison.rs | 1 + soroban-env-host/src/host/conversion.rs | 2 + soroban-env-host/src/host/crypto.rs | 4 + soroban-env-host/src/host/frame.rs | 2 + soroban-env-host/src/host/metered_map.rs | 2 + soroban-env-host/src/host/metered_vector.rs | 1 + soroban-env-host/src/host/metered_xdr.rs | 3 + soroban-env-host/src/host_object.rs | 2 + soroban-env-host/src/lib.rs | 20 +++ .../src/native_contract/token/contract.rs | 18 ++ soroban-env-host/src/storage.rs | 5 + soroban-env-host/src/vm.rs | 31 ++-- soroban-env-host/src/vm/dispatch.rs | 2 + 19 files changed, 281 insertions(+), 14 deletions(-) diff --git a/Cargo.lock b/Cargo.lock index 5476418d8..b9427252a 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -517,6 +517,19 @@ dependencies = [ "percent-encoding", ] +[[package]] +name = "generator" +version = "0.7.5" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "5cc16584ff22b460a382b7feec54b23d2908d858152e5739a120b949293bd74e" +dependencies = [ + "cc", + "libc", + "log", + "rustversion", + "windows", +] + [[package]] name = "generic-array" version = "0.14.7" @@ -783,6 +796,28 @@ dependencies = [ "cfg-if", ] +[[package]] +name = "loom" +version = "0.5.6" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "ff50ecb28bb86013e935fb6683ab1f6d3a20016f123c76fd4c27470076ac30f5" +dependencies = [ + "cfg-if", + "generator", + "scoped-tls", + "tracing", + "tracing-subscriber", +] + +[[package]] +name = "matchers" +version = "0.1.0" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "8263075bb86c5a1b1427b5ae862e8889656f126e9f77c484496e8b47cf5c5558" +dependencies = [ + "regex-automata", +] + [[package]] name = "matrixmultiply" version = "0.3.7" @@ -857,6 +892,16 @@ version = "1.2.4" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "a5b8c256fd9471521bcb84c3cdba98921497f1a331cbc15b8030fc63b82050ce" +[[package]] +name = "nu-ansi-term" +version = "0.46.0" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "77a8165726e8236064dbb45459242600304b42a5ea24ee2948e18e023bf7ba84" +dependencies = [ + "overload", + "winapi", +] + [[package]] name = "num-bigint" version = "0.4.3" @@ -939,6 +984,12 @@ version = "0.3.0" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "624a8340c38c1b80fd549087862da4ba43e08858af025b236e509b6649fc13d5" +[[package]] +name = "overload" +version = "0.1.1" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "b15813163c1d831bf4a13c3610c05c0d03b39feb07f7e09fa234dac9b15aaf39" + [[package]] name = "paste" version = "1.0.12" @@ -1108,9 +1159,24 @@ checksum = "d1a59b5d8e97dee33696bf13c5ba8ab85341c002922fba050069326b9c498974" dependencies = [ "aho-corasick", "memchr", - "regex-syntax", + "regex-syntax 0.7.2", +] + +[[package]] +name = "regex-automata" +version = "0.1.10" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "6c230d73fb8d8c1b9c0b3135c5142a8acee3a0558fb8db5cf1cb65f8d7862132" +dependencies = [ + "regex-syntax 0.6.29", ] +[[package]] +name = "regex-syntax" +version = "0.6.29" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "f162c6dd7b008981e4d40210aca20b4bd0f9b60ca9271061b07f78537722f2e1" + [[package]] name = "regex-syntax" version = "0.7.2" @@ -1142,6 +1208,12 @@ version = "0.1.23" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "d626bb9dae77e28219937af045c257c28bfd3f69333c512553507f5f9798cb76" +[[package]] +name = "rustversion" +version = "1.0.13" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "dc31bd9b61a32c31f9650d18add92aa83a49ba979c143eefd27fe7177b05bd5f" + [[package]] name = "ryu" version = "1.0.13" @@ -1157,6 +1229,12 @@ dependencies = [ "bytemuck", ] +[[package]] +name = "scoped-tls" +version = "1.0.1" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "e1cf6437eb19a8f4a6cc0f7dca544973b0b78843adbfeb3683d1a94a0024a294" + [[package]] name = "sec1" version = "0.7.2" @@ -1264,6 +1342,15 @@ dependencies = [ "keccak", ] +[[package]] +name = "sharded-slab" +version = "0.1.4" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "900fba806f70c630b0a382d0d825e17a0f19fcd059a2ade1ff237bcddf446b31" +dependencies = [ + "lazy_static", +] + [[package]] name = "signature" version = "1.6.4" @@ -1361,6 +1448,7 @@ dependencies = [ "textplots", "thousands", "tracking-allocator", + "tracy-client", "wasmprinter", ] @@ -1595,6 +1683,16 @@ version = "0.2.0" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "3bf63baf9f5039dadc247375c29eb13706706cfde997d0330d05aa63a77d8820" +[[package]] +name = "thread_local" +version = "1.1.7" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "3fdd6f064ccff2d6567adcb3873ca630700f00b5ad3f060c25b5dcfd9a4ce152" +dependencies = [ + "cfg-if", + "once_cell", +] + [[package]] name = "time" version = "0.3.21" @@ -1662,9 +1760,21 @@ checksum = "8ce8c33a8d48bd45d624a6e523445fd21ec13d3653cd51f681abf67418f54eb8" dependencies = [ "cfg-if", "pin-project-lite", + "tracing-attributes", "tracing-core", ] +[[package]] +name = "tracing-attributes" +version = "0.1.26" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "5f4f31f56159e98206da9efd823404b79b6ef3143b4a7ab76e67b1751b25a4ab" +dependencies = [ + "proc-macro2", + "quote", + "syn 2.0.16", +] + [[package]] name = "tracing-core" version = "0.1.31" @@ -1672,6 +1782,18 @@ source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "0955b8137a1df6f1a2e9a37d8a6656291ff0297c1a97c24e0d8425fe2312f79a" dependencies = [ "once_cell", + "valuable", +] + +[[package]] +name = "tracing-log" +version = "0.1.3" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "78ddad33d2d10b1ed7eb9d1f518a5674713876e97e5bb9b7345a7984fbb4f922" +dependencies = [ + "lazy_static", + "log", + "tracing-core", ] [[package]] @@ -1680,7 +1802,16 @@ version = "0.3.17" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "30a651bc37f915e81f087d86e62a18eec5f79550c7faff886f7090b4ea757c77" dependencies = [ + "matchers", + "nu-ansi-term", + "once_cell", + "regex", + "sharded-slab", + "smallvec", + "thread_local", + "tracing", "tracing-core", + "tracing-log", ] [[package]] @@ -1693,6 +1824,26 @@ dependencies = [ "tracing-subscriber", ] +[[package]] +name = "tracy-client" +version = "0.15.2" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "434ecabbda9f67eeea1eab44d52f4a20538afa3e2c2770f2efc161142b25b608" +dependencies = [ + "loom", + "once_cell", + "tracy-client-sys", +] + +[[package]] +name = "tracy-client-sys" +version = "0.21.0" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "0d99f5fc382239d08b6bf05bb6206a585bfdb988c878f2499081d0f285ef7819" +dependencies = [ + "cc", +] + [[package]] name = "typenum" version = "1.16.0" @@ -1743,6 +1894,12 @@ dependencies = [ "percent-encoding", ] +[[package]] +name = "valuable" +version = "0.1.0" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "830b7e5d4d90034032940e4ace0d9a9a057e7a45cd94e6c007832e39edb82f6d" + [[package]] name = "vec_map" version = "0.8.2" diff --git a/deny.toml b/deny.toml index eea5da899..e41b44980 100644 --- a/deny.toml +++ b/deny.toml @@ -49,7 +49,15 @@ exclude = [ "num-derive", "zeroize_derive", # also a not upgraded to syn 2, but just a dev-dep anyway - "int-enum" + "int-enum", + # the dep specs of tracy-client are weird and include "loom" which it + # totally doesn't depend on but in any case it's compiled-out in real + # production builds we care about. + "tracy-client", + # Somehow the tracking machinery of two different dev-dep tracing + # subsystems also winds up pulling in conflicts, but again, just + # dev-deps or non-produciton configs. + "tracking-allocator" ] # If true, metadata will be collected with `--all-features`. Note that this can't diff --git a/soroban-env-host/Cargo.toml b/soroban-env-host/Cargo.toml index 29b4b704a..15bf46ff5 100644 --- a/soroban-env-host/Cargo.toml +++ b/soroban-env-host/Cargo.toml @@ -37,6 +37,9 @@ k256 = {version = "0.13.1", features=["ecdsa", "arithmetic"]} getrandom = { version = "0.2", features=["js"] } sha3 = "0.10.8" +[target.'cfg(not(target_family = "wasm"))'.dependencies] +tracy-client = { version = "=0.15.2", features = ["enable", "timer-fallback"], default-features = false, optional = true } + [dev-dependencies] env_logger = "0.9.0" itertools = "0.10.3" @@ -55,6 +58,7 @@ linregress = "0.5.1" [features] testutils = ["soroban-env-common/testutils"] +tracy = ["dep:tracy-client"] [target.'cfg(target_os = "linux")'.dev-dependencies] perf-event = "0.4.7" diff --git a/soroban-env-host/src/auth.rs b/soroban-env-host/src/auth.rs index 26aba98e0..b9d0017e0 100644 --- a/soroban-env-host/src/auth.rs +++ b/soroban-env-host/src/auth.rs @@ -599,6 +599,7 @@ impl AuthorizationManager { address: AddressObject, args: Vec, ) -> Result<(), HostError> { + let _span = tracy_span!("require auth"); let authorized_function = self .try_borrow_call_stack(host)? .last() @@ -810,6 +811,7 @@ impl AuthorizationManager { // Returns a snapshot of `AuthorizationManager` to use for rollback. pub(crate) fn snapshot(&self, host: &Host) -> Result { + let _span = tracy_span!("snapshot auth"); let account_trackers_snapshot = match &self.mode { AuthorizationMode::Enforcing => AccountTrackersSnapshot::Enforcing( self.try_borrow_account_trackers(host)? @@ -858,6 +860,7 @@ impl AuthorizationManager { host: &Host, snapshot: AuthorizationManagerSnapshot, ) -> Result<(), HostError> { + let _span = tracy_span!("rollback auth"); match snapshot.account_trackers_snapshot { AccountTrackersSnapshot::Enforcing(trackers_snapshot) => { let trackers = self.try_borrow_account_trackers(host)?; @@ -942,6 +945,7 @@ impl AuthorizationManager { // Records a new call stack frame. // This should be called for every `Host` `push_frame`. pub(crate) fn push_frame(&self, host: &Host, frame: &Frame) -> Result<(), HostError> { + let _span = tracy_span!("push auth frame"); let (contract_id, function_name) = match frame { Frame::ContractVM { vm, fn_name, .. } => { (vm.contract_id.metered_clone(host.budget_ref())?, *fn_name) @@ -970,6 +974,7 @@ impl AuthorizationManager { // Pops a call stack frame. // This should be called for every `Host` `pop_frame`. pub(crate) fn pop_frame(&self, host: &Host) -> Result<(), HostError> { + let _span = tracy_span!("pop auth frame"); { let mut call_stack = self.try_borrow_call_stack_mut(host)?; // Currently we don't push host function call frames, hence this may be diff --git a/soroban-env-host/src/budget.rs b/soroban-env-host/src/budget.rs index cd24843d6..be4744b6d 100644 --- a/soroban-env-host/src/budget.rs +++ b/soroban-env-host/src/budget.rs @@ -449,9 +449,18 @@ impl DepthLimiter for BudgetImpl { } } -#[derive(Default, Clone)] +#[derive(Clone)] pub struct Budget(pub(crate) Rc>); +#[allow(clippy::derivable_impls)] +impl Default for Budget { + fn default() -> Self { + #[cfg(all(not(target_family = "wasm"), feature = "tracy"))] + let _client = tracy_client::Client::start(); + Self(Default::default()) + } +} + impl Debug for Budget { fn fmt(&self, f: &mut std::fmt::Formatter<'_>) -> std::fmt::Result { writeln!(f, "{:?}", self.0.try_borrow().map_err(|_| std::fmt::Error)?) diff --git a/soroban-env-host/src/host.rs b/soroban-env-host/src/host.rs index b8ce13f48..d770a6e63 100644 --- a/soroban-env-host/src/host.rs +++ b/soroban-env-host/src/host.rs @@ -136,9 +136,18 @@ pub(crate) struct HostImpl { previous_authorization_manager: RefCell>, } // Host is a newtype on Rc so we can impl Env for it below. -#[derive(Default, Clone)] +#[derive(Clone)] pub struct Host(pub(crate) Rc); +#[allow(clippy::derivable_impls)] +impl Default for Host { + fn default() -> Self { + #[cfg(all(not(target_family = "wasm"), feature = "tracy"))] + let _client = tracy_client::Client::start(); + Self(Default::default()) + } +} + macro_rules! impl_checked_borrow_helpers { ($field:ident, $t:ty, $borrow:ident, $borrow_mut:ident) => { impl Host { @@ -244,6 +253,8 @@ impl Host { /// contract-data access functions such as /// [`Env::get_contract_data`]. pub fn with_storage_and_budget(storage: Storage, budget: Budget) -> Self { + #[cfg(all(not(target_family = "wasm"), feature = "tracy"))] + let _client = tracy_client::Client::start(); Self(Rc::new(HostImpl { source_account: RefCell::new(None), ledger: RefCell::new(None), diff --git a/soroban-env-host/src/host/comparison.rs b/soroban-env-host/src/host/comparison.rs index dc2d88dd2..d5edaa049 100644 --- a/soroban-env-host/src/host/comparison.rs +++ b/soroban-env-host/src/host/comparison.rs @@ -52,6 +52,7 @@ impl Compare for Host { fn compare(&self, a: &HostObject, b: &HostObject) -> Result { use HostObject::*; + let _span = tracy_span!("Compare"); // This is the depth limit checkpoint for `Val` comparison. self.budget_cloned().with_limited_depth(|_| { match (a, b) { diff --git a/soroban-env-host/src/host/conversion.rs b/soroban-env-host/src/host/conversion.rs index 49427ec5c..55315236b 100644 --- a/soroban-env-host/src/host/conversion.rs +++ b/soroban-env-host/src/host/conversion.rs @@ -370,6 +370,7 @@ impl Host { // For an `Object`, the actual structural conversion (such as byte // cloning) occurs in `from_host_obj` and is metered there. // This is the depth limit checkpoint for `Val`->`ScVal` conversion. + let _span = tracy_span!("Val to ScVal"); self.budget_cloned().with_limited_depth(|_| { self.charge_budget(ContractCostType::ValXdrConv, None)?; ScVal::try_from_val(self, &val).map_err(|_| { @@ -384,6 +385,7 @@ impl Host { } pub(crate) fn to_host_val(&self, v: &ScVal) -> Result { + let _span = tracy_span!("ScVal to Val"); // This is the depth limit checkpoint for `ScVal`->`Val` conversion. self.budget_cloned().with_limited_depth(|_| { self.charge_budget(ContractCostType::ValXdrConv, None)?; diff --git a/soroban-env-host/src/host/crypto.rs b/soroban-env-host/src/host/crypto.rs index 1cf789077..6ebd382e7 100644 --- a/soroban-env-host/src/host/crypto.rs +++ b/soroban-env-host/src/host/crypto.rs @@ -55,6 +55,7 @@ impl Host { public_key: &ed25519_dalek::PublicKey, sig: &ed25519_dalek::Signature, ) -> Result<(), HostError> { + let _span = tracy_span!("ed25519 verify"); self.charge_budget( ContractCostType::VerifyEd25519Sig, Some(payload.len() as u64), @@ -162,6 +163,7 @@ impl Host { sig: &k256::ecdsa::Signature, rid: k256::ecdsa::RecoveryId, ) -> Result { + let _span = tracy_span!("secp256k1 recover"); self.charge_budget(ContractCostType::RecoverEcdsaSecp256k1Key, None)?; let recovered_key = k256::ecdsa::VerifyingKey::recover_from_prehash(hash.as_slice(), &sig, rid).map_err( @@ -183,6 +185,7 @@ impl Host { // SHA256 functions pub(crate) fn sha256_hash_from_bytes(&self, bytes: &[u8]) -> Result, HostError> { + let _span = tracy_span!("sha256"); self.charge_budget( ContractCostType::ComputeSha256Hash, Some(bytes.len() as u64), @@ -208,6 +211,7 @@ impl Host { // Keccak256/SHA3 functions pub(crate) fn keccak256_hash_from_bytes(&self, bytes: &[u8]) -> Result, HostError> { + let _span = tracy_span!("keccak256"); self.charge_budget( ContractCostType::ComputeKeccak256Hash, Some(bytes.len() as u64), diff --git a/soroban-env-host/src/host/frame.rs b/soroban-env-host/src/host/frame.rs index 7a865bd23..c257521ce 100644 --- a/soroban-env-host/src/host/frame.rs +++ b/soroban-env-host/src/host/frame.rs @@ -123,6 +123,7 @@ impl Host { /// operation fails, it can be used to roll the [`Host`] back to the state /// it had before its associated [`Frame`] was pushed. pub(super) fn push_frame(&self, frame: Frame) -> Result { + let _span = tracy_span!("push frame"); let auth_manager = self.try_borrow_authorization_manager()?; let auth_snapshot = auth_manager.snapshot(self)?; auth_manager.push_frame(self, &frame)?; @@ -144,6 +145,7 @@ impl Host { /// the current context and optionally rolls back the [`Host`]'s objects /// and storage map to the state in the provided [`RollbackPoint`]. pub(super) fn pop_frame(&self, orp: Option) -> Result<(), HostError> { + let _span = tracy_span!("pop frame"); // Instance storage is tied to the frame and only exists in-memory. So // instead of snapshotting it and rolling it back, we just flush the // changes only when rollback is not needed. diff --git a/soroban-env-host/src/host/metered_map.rs b/soroban-env-host/src/host/metered_map.rs index ce7f60906..0af96b974 100644 --- a/soroban-env-host/src/host/metered_map.rs +++ b/soroban-env-host/src/host/metered_map.rs @@ -111,6 +111,7 @@ where iter: I, ctx: &Ctx, ) -> Result { + let _span = tracy_span!("new map"); if let (_, Some(sz)) = iter.size_hint() { // It's possible we temporarily go over-budget here before charging, but // only by the cost of temporarily allocating twice the size of our largest @@ -131,6 +132,7 @@ where K: Borrow, Ctx: Compare, { + let _span = tracy_span!("map lookup"); self.charge_binsearch(ctx)?; let mut err: Option = None; let res = self.map.binary_search_by(|probe| { diff --git a/soroban-env-host/src/host/metered_vector.rs b/soroban-env-host/src/host/metered_vector.rs index c9416d260..d0ea2fba0 100644 --- a/soroban-env-host/src/host/metered_vector.rs +++ b/soroban-env-host/src/host/metered_vector.rs @@ -94,6 +94,7 @@ where iter: I, budget: &Budget, ) -> Result { + let _span = tracy_span!("new vec"); if let (_, Some(sz)) = iter.size_hint() { // It's possible we temporarily go over-budget here before charging, but // only by the cost of temporarily allocating twice the size of our largest diff --git a/soroban-env-host/src/host/metered_xdr.rs b/soroban-env-host/src/host/metered_xdr.rs index e9120f2d4..16ac54b7e 100644 --- a/soroban-env-host/src/host/metered_xdr.rs +++ b/soroban-env-host/src/host/metered_xdr.rs @@ -37,6 +37,7 @@ impl Host { obj: &impl WriteXdr, w: &mut Vec, ) -> Result<(), HostError> { + let _span = tracy_span!("write xdr"); let mw = MeteredWrite { host: self, w }; let mut w = DepthLimitedWrite::new(mw, DEFAULT_XDR_RW_DEPTH_LIMIT); // MeteredWrite above turned any budget failure into an IO error; we turn it @@ -47,6 +48,7 @@ impl Host { } pub(crate) fn metered_hash_xdr(&self, obj: &impl WriteXdr) -> Result<[u8; 32], HostError> { + let _span = tracy_span!("hash xdr"); let mut buf = vec![]; self.metered_write_xdr(obj, &mut buf)?; self.charge_budget(ContractCostType::ComputeSha256Hash, Some(buf.len() as u64))?; @@ -54,6 +56,7 @@ impl Host { } pub(crate) fn metered_from_xdr(&self, bytes: &[u8]) -> Result { + let _span = tracy_span!("read xdr"); self.charge_budget(ContractCostType::ValDeser, Some(bytes.len() as u64))?; self.map_err(T::from_xdr(bytes)) } diff --git a/soroban-env-host/src/host_object.rs b/soroban-env-host/src/host_object.rs index dd3b0c038..c25648de8 100644 --- a/soroban-env-host/src/host_object.rs +++ b/soroban-env-host/src/host_object.rs @@ -313,6 +313,7 @@ impl Host { &self, hot: HOT, ) -> Result { + let _span = tracy_span!("add host object"); let index = self.try_borrow_objects()?.len(); let handle = index_to_handle(self, index, false)?; // charge for the new host object, which is just the amortized cost of a single @@ -332,6 +333,7 @@ impl Host { where F: FnOnce(Option<&HostObject>) -> Result, { + let _span = tracy_span!("visit host object"); self.charge_budget(ContractCostType::VisitObject, None)?; let r = self.try_borrow_objects()?; let obj: Object = obj.into(); diff --git a/soroban-env-host/src/lib.rs b/soroban-env-host/src/lib.rs index 55d857a53..dbb3c76c8 100644 --- a/soroban-env-host/src/lib.rs +++ b/soroban-env-host/src/lib.rs @@ -23,6 +23,26 @@ //! between contracts and their durable storage. //! +#[cfg(all(not(target_family = "wasm"), feature = "tracy"))] +macro_rules! tracy_span { + () => { + tracy_client::span!() + }; + ($name:expr) => { + tracy_client::span!($name) + }; +} + +#[cfg(any(target_family = "wasm", not(feature = "tracy")))] +macro_rules! tracy_span { + () => { + () + }; + ($name:expr) => { + () + }; +} + pub mod budget; pub mod events; pub use events::diagnostic::DiagnosticLevel; diff --git a/soroban-env-host/src/native_contract/token/contract.rs b/soroban-env-host/src/native_contract/token/contract.rs index 4e35c9fde..cbf1a1a19 100644 --- a/soroban-env-host/src/native_contract/token/contract.rs +++ b/soroban-env-host/src/native_contract/token/contract.rs @@ -111,6 +111,7 @@ fn check_non_native(e: &Host) -> Result<(), HostError> { // Metering: *mostly* covered by components. impl TokenTrait for Token { fn init_asset(e: &Host, asset_bytes: Bytes) -> Result<(), HostError> { + let _span = tracy_span!("native token init_asset"); if has_asset_info(e)? { return Err(e.error( ContractError::AlreadyInitializedError.into(), @@ -181,6 +182,7 @@ impl TokenTrait for Token { } fn allowance(e: &Host, from: Address, spender: Address) -> Result { + let _span = tracy_span!("native token allowance"); e.bump_current_contract_instance_and_code(INSTANCE_BUMP_AMOUNT.into())?; read_allowance(e, from, spender) } @@ -193,6 +195,7 @@ impl TokenTrait for Token { amount: i128, expiration_ledger: u32, ) -> Result<(), HostError> { + let _span = tracy_span!("native token approve"); check_nonnegative_amount(e, amount)?; from.require_auth()?; @@ -205,23 +208,27 @@ impl TokenTrait for Token { // Metering: covered by components fn balance(e: &Host, addr: Address) -> Result { + let _span = tracy_span!("native token balance"); e.bump_current_contract_instance_and_code(INSTANCE_BUMP_AMOUNT.into())?; read_balance(e, addr) } fn spendable_balance(e: &Host, addr: Address) -> Result { + let _span = tracy_span!("native token spendable balance"); e.bump_current_contract_instance_and_code(INSTANCE_BUMP_AMOUNT.into())?; get_spendable_balance(e, addr) } // Metering: covered by components fn authorized(e: &Host, addr: Address) -> Result { + let _span = tracy_span!("native token authorized"); e.bump_current_contract_instance_and_code(INSTANCE_BUMP_AMOUNT.into())?; is_authorized(e, addr) } // Metering: covered by components fn transfer(e: &Host, from: Address, to: Address, amount: i128) -> Result<(), HostError> { + let _span = tracy_span!("native token transfer"); check_nonnegative_amount(e, amount)?; from.require_auth()?; @@ -241,6 +248,7 @@ impl TokenTrait for Token { to: Address, amount: i128, ) -> Result<(), HostError> { + let _span = tracy_span!("native token transfer_from"); check_nonnegative_amount(e, amount)?; spender.require_auth()?; @@ -255,6 +263,7 @@ impl TokenTrait for Token { // Metering: covered by components fn burn(e: &Host, from: Address, amount: i128) -> Result<(), HostError> { + let _span = tracy_span!("native token burn"); check_nonnegative_amount(e, amount)?; check_non_native(e)?; from.require_auth()?; @@ -268,6 +277,7 @@ impl TokenTrait for Token { // Metering: covered by components fn burn_from(e: &Host, spender: Address, from: Address, amount: i128) -> Result<(), HostError> { + let _span = tracy_span!("native token burn_from"); check_nonnegative_amount(e, amount)?; check_non_native(e)?; spender.require_auth()?; @@ -282,6 +292,7 @@ impl TokenTrait for Token { // Metering: covered by components fn clawback(e: &Host, from: Address, amount: i128) -> Result<(), HostError> { + let _span = tracy_span!("native token clawback"); check_nonnegative_amount(e, amount)?; check_clawbackable(e, from.clone())?; let admin = read_administrator(e)?; @@ -296,6 +307,7 @@ impl TokenTrait for Token { // Metering: covered by components fn set_authorized(e: &Host, addr: Address, authorize: bool) -> Result<(), HostError> { + let _span = tracy_span!("native token set_authorized"); let admin = read_administrator(e)?; admin.require_auth()?; @@ -308,6 +320,7 @@ impl TokenTrait for Token { // Metering: covered by components fn mint(e: &Host, to: Address, amount: i128) -> Result<(), HostError> { + let _span = tracy_span!("native token mint"); check_nonnegative_amount(e, amount)?; let admin = read_administrator(e)?; admin.require_auth()?; @@ -321,6 +334,7 @@ impl TokenTrait for Token { // Metering: covered by components fn set_admin(e: &Host, new_admin: Address) -> Result<(), HostError> { + let _span = tracy_span!("native token set_admin"); let admin = read_administrator(e)?; admin.require_auth()?; @@ -332,19 +346,23 @@ impl TokenTrait for Token { } fn admin(e: &Host) -> Result { + let _span = tracy_span!("native token admin"); read_administrator(e) } fn decimals(_e: &Host) -> Result { + let _span = tracy_span!("native token decimals"); // no need to load metadata since this is fixed for all SAC tokens Ok(DECIMAL) } fn name(e: &Host) -> Result { + let _span = tracy_span!("native token name"); read_name(e) } fn symbol(e: &Host) -> Result { + let _span = tracy_span!("native token symbol"); read_symbol(e) } } diff --git a/soroban-env-host/src/storage.rs b/soroban-env-host/src/storage.rs index 2db037ed4..f95357fa3 100644 --- a/soroban-env-host/src/storage.rs +++ b/soroban-env-host/src/storage.rs @@ -195,6 +195,7 @@ impl Storage { key: &Rc, budget: &Budget, ) -> Result, HostError> { + let _span = tracy_span!("storage get"); let ty = AccessType::ReadOnly; match self.mode { FootprintMode::Recording(ref src) => { @@ -253,6 +254,7 @@ impl Storage { val: &Rc, budget: &Budget, ) -> Result<(), HostError> { + let _span = tracy_span!("storage put"); self.put_opt(key, Some(val), budget) } @@ -266,6 +268,7 @@ impl Storage { /// [LedgerKey] has been declared in the [Footprint] as /// [AccessType::ReadWrite]. pub fn del(&mut self, key: &Rc, budget: &Budget) -> Result<(), HostError> { + let _span = tracy_span!("storage del"); self.put_opt(key, None, budget) } @@ -279,6 +282,7 @@ impl Storage { /// In [FootprintMode::Enforcing] mode, succeeds only if the access has been /// declared in the [Footprint]. pub fn has(&mut self, key: &Rc, budget: &Budget) -> Result { + let _span = tracy_span!("storage has"); let ty = AccessType::ReadOnly; match self.mode { FootprintMode::Recording(ref src) => { @@ -309,6 +313,7 @@ impl Storage { /// In [FootprintMode::Enforcing] mode, succeeds only if the access has been /// declared in the [Footprint]. pub fn touch_key(&mut self, key: &Rc, budget: &Budget) -> Result<(), HostError> { + let _span = tracy_span!("touch key"); let ty = AccessType::ReadOnly; match self.mode { FootprintMode::Recording(_) => self.footprint.record_access(key, ty, budget), diff --git a/soroban-env-host/src/vm.rs b/soroban-env-host/src/vm.rs index c4441d6f8..f67b1045c 100644 --- a/soroban-env-host/src/vm.rs +++ b/soroban-env-host/src/vm.rs @@ -33,7 +33,6 @@ use wasmi::{Engine, FuelConsumptionMode, Func, Instance, Linker, Memory, Module, use crate::VmCaller; #[cfg(any(test, feature = "testutils"))] use wasmi::{Caller, StoreContextMut}; - impl wasmi::core::HostError for HostError {} /// A [Vm] is a thin wrapper around an instance of [wasmi::Module]. Multiple @@ -140,6 +139,8 @@ impl Vm { contract_id: Hash, module_wasm_code: &[u8], ) -> Result, HostError> { + let _span = tracy_span!("Vm::new"); + host.charge_budget( ContractCostType::VmInstantiation, Some(module_wasm_code.len() as u64), @@ -160,7 +161,10 @@ impl Vm { .set_fuel_costs(fuel_costs); let engine = Engine::new(&config); - let module = host.map_err(Module::new(&engine, module_wasm_code))?; + let module = { + let _span0 = tracy_span!("parse module"); + host.map_err(Module::new(&engine, module_wasm_code))? + }; Self::check_meta_section(host, &module)?; @@ -169,16 +173,22 @@ impl Vm { let mut linker = >::new(&engine); - for hf in HOST_FUNCTIONS { - let func = (hf.wrap)(&mut store); - host.map_err( - linker - .define(hf.mod_str, hf.fn_str, func) - .map_err(|le| wasmi::Error::Linker(le)), - )?; + { + let _span0 = tracy_span!("define host functions"); + for hf in HOST_FUNCTIONS { + let func = (hf.wrap)(&mut store); + host.map_err( + linker + .define(hf.mod_str, hf.fn_str, func) + .map_err(|le| wasmi::Error::Linker(le)), + )?; + } } - let not_started_instance = host.map_err(linker.instantiate(&mut store, &module))?; + let not_started_instance = { + let _span0 = tracy_span!("instantiate module"); + host.map_err(linker.instantiate(&mut store, &module))? + }; let instance = host.map_err( not_started_instance @@ -287,6 +297,7 @@ impl Vm { func_sym: &Symbol, args: &[Val], ) -> Result { + let _span = tracy_span!("Vm::invoke_function_raw"); host.charge_budget(ContractCostType::InvokeVmFunction, None)?; let wasm_args: Vec = args .iter() diff --git a/soroban-env-host/src/vm/dispatch.rs b/soroban-env-host/src/vm/dispatch.rs index e62d61327..fe7eb308e 100644 --- a/soroban-env-host/src/vm/dispatch.rs +++ b/soroban-env-host/src/vm/dispatch.rs @@ -139,6 +139,8 @@ macro_rules! generate_dispatch_functions { pub(crate) fn $fn_id(mut caller: wasmi::Caller, $($arg:i64),*) -> Result<(i64,), Trap> { + let _span = tracy_span!(std::stringify!($fn_id)); + // Notes on metering: a flat charge per host function invocation. // This does not account for the actual work being done in those functions, // which are accounted for individually at the operation level.