Sphinx packet processing CPU cycles measurement (#3247)

* POC measurement * parent ce76790761 author durch <durch@users.noreply.github.com> 1680116778 +0200 committer durch <durch@users.noreply.github.com> 1680683399 +0200 Instrument packet processing * Cleanup and format * Feature gate tracing * Add .gitkeep to wallet dist * Squashed commit of the following: commit 0b1b6947e8 Author: Jon Häggblad <jon.haggblad@gmail.com> Date: Wed Apr 5 11:28:28 2023 +0200 Replace mobile flag with target_os = android (#3278) * Remove old lock file * Start replacing mobile with android * Regex replace all mobile with android * Remove the mobile feature flag * keep the cfg mobile in tauri commit c79b2cfb78 Author: Jon Häggblad <jon.haggblad@gmail.com> Date: Wed Apr 5 11:27:38 2023 +0200 Service provider directory contract (#3220) * first commit of service provider directory contract proof of concept * *added config set on instantiation, *removed greetQuery test function * commit before mapping change * *changed mapping of service to use client address instead of cosmos addr * commit before mapping change * added acl to delete() * added test for acl in delete() * changed whitelist<vec> to standrd_whitelist bool in Service struct * removed old comments and commented out code * rustfmt * wup * wup * Older version of cw-multi-test that works with 1.0.0 * wip * Remove .gitignore * Basic tests for announce and query now works * Restore tests for delete as well * Consolidate tests * Tidy * fmt * Start reworking test helpers * Tidy tests * More test work * More test improvements * More work on tests * Tweaks * Further tests * rustfmt * Add some comments * Initial work on requiring deposit * wip * Work on updating tests for handling funds * Start updating integration tests * Integration tests updated * merge test mods in state * Address review comments * Enable wasm-opt * Unify Result type * consistent amount in error type * WIP: paging output * IndexedMap working * extract to config file * WIP: middle of extracting out types * Extract types * wip * Types now extracted out: * Paged response type too * rustfmt * Start working on switching to cw Admin * Complete switch to Admin * Remove owner from announce msg * remove unused imports * Assert owner * Extract out types to common crate * Fix test compilation * Add query by owner and nym address * Move msg to common crate * rustfmt * tests for service id * service storage tests * state services tests * function rename * tidy * Fix clippy warning * User ServiceId instead and not u32 * Delete by nym address * Emit explicit events * Swap ToString for Display * Move all storage keys to constants.rs * clippy * Test for deleting by name * Tidy integration tests * Remove to_string * Some comments to tests * Integration test for paging * serde snake_csae for NymAddress and ServiceType * Add migrate entry point * Add query contract version * A few more asserts for balance * Make MigrateMsg a struct --------- Co-authored-by: mx <maxhampshire@pm.me> commit dd699bce9a Merge: 5ce017ef3 e6957e7a9 Author: Tommy Verrall <60836166+tommyv1987@users.noreply.github.com> Date: Wed Apr 5 10:18:16 2023 +0100 Merge pull request #3235 from nymtech/feature/performance-active-set-selection Feature/performance active set selection commit 5ce017ef3d Author: benedetta davico <46782255+benedettadavico@users.noreply.github.com> Date: Wed Apr 5 10:57:45 2023 +0200 adding vesting tests (#3279) commit 59c1ce2639 Merge: 4fb63d889 276edfd56 Author: Tommy Verrall <60836166+tommyv1987@users.noreply.github.com> Date: Wed Apr 5 09:50:53 2023 +0100 Merge pull request #3261 from nymtech/feature/refresh-allow-list Feature/refresh allow list commit 4fb63d8892 Author: Jędrzej Stuczyński <jedrzej.stuczynski@gmail.com> Date: Wed Apr 5 09:22:43 2023 +0100 Feature/vesting delegation amount query (#3229) * moved queries and transactions out of contract.rs * added queries for vesting delegation details * nyxd_client support commit 276edfd562 Author: Jędrzej Stuczyński <jedrzej.stuczynski@gmail.com> Date: Fri Mar 31 15:56:21 2023 +0100 clippy commit 605f8fcde3 Author: Jędrzej Stuczyński <jedrzej.stuczynski@gmail.com> Date: Fri Mar 31 15:06:12 2023 +0100 updated and cleaned up tests commit f0e4d1a7cf Author: Jędrzej Stuczyński <jedrzej.stuczynski@gmail.com> Date: Fri Mar 31 14:01:36 2023 +0100 configurable stored lists locations commit 055ec4bdd5 Author: Jędrzej Stuczyński <jedrzej.stuczynski@gmail.com> Date: Fri Mar 31 12:57:02 2023 +0100 updating stored allow list on file changes commit 5761f9ac7f Author: Jędrzej Stuczyński <jedrzej.stuczynski@gmail.com> Date: Fri Mar 31 12:15:45 2023 +0100 file watcher commit 32620fd55f Author: Jędrzej Stuczyński <jedrzej.stuczynski@gmail.com> Date: Thu Mar 30 17:47:12 2023 +0100 updating standard list in a timer commit abb5cdbe06 Author: Jędrzej Stuczyński <jedrzej.stuczynski@gmail.com> Date: Thu Mar 30 16:43:58 2023 +0100 extracted domain and ipnet information to separate struct commit e6957e7a99 Author: Jędrzej Stuczyński <jedrzej.stuczynski@gmail.com> Date: Tue Mar 28 11:25:43 2023 +0100 use combination of stake and performance for rewarded set selection commit de2406a2c7 Author: Jędrzej Stuczyński <jedrzej.stuczynski@gmail.com> Date: Tue Mar 28 10:54:14 2023 +0100 Moved MixnodeWithPerformance to helpers * Squashed commit of the following: commit 0b1b6947e8 Author: Jon Häggblad <jon.haggblad@gmail.com> Date: Wed Apr 5 11:28:28 2023 +0200 Replace mobile flag with target_os = android (#3278) * Remove old lock file * Start replacing mobile with android * Regex replace all mobile with android * Remove the mobile feature flag * keep the cfg mobile in tauri commit c79b2cfb78 Author: Jon Häggblad <jon.haggblad@gmail.com> Date: Wed Apr 5 11:27:38 2023 +0200 Service provider directory contract (#3220) * first commit of service provider directory contract proof of concept * *added config set on instantiation, *removed greetQuery test function * commit before mapping change * *changed mapping of service to use client address instead of cosmos addr * commit before mapping change * added acl to delete() * added test for acl in delete() * changed whitelist<vec> to standrd_whitelist bool in Service struct * removed old comments and commented out code * rustfmt * wup * wup * Older version of cw-multi-test that works with 1.0.0 * wip * Remove .gitignore * Basic tests for announce and query now works * Restore tests for delete as well * Consolidate tests * Tidy * fmt * Start reworking test helpers * Tidy tests * More test work * More test improvements * More work on tests * Tweaks * Further tests * rustfmt * Add some comments * Initial work on requiring deposit * wip * Work on updating tests for handling funds * Start updating integration tests * Integration tests updated * merge test mods in state * Address review comments * Enable wasm-opt * Unify Result type * consistent amount in error type * WIP: paging output * IndexedMap working * extract to config file * WIP: middle of extracting out types * Extract types * wip * Types now extracted out: * Paged response type too * rustfmt * Start working on switching to cw Admin * Complete switch to Admin * Remove owner from announce msg * remove unused imports * Assert owner * Extract out types to common crate * Fix test compilation * Add query by owner and nym address * Move msg to common crate * rustfmt * tests for service id * service storage tests * state services tests * function rename * tidy * Fix clippy warning * User ServiceId instead and not u32 * Delete by nym address * Emit explicit events * Swap ToString for Display * Move all storage keys to constants.rs * clippy * Test for deleting by name * Tidy integration tests * Remove to_string * Some comments to tests * Integration test for paging * serde snake_csae for NymAddress and ServiceType * Add migrate entry point * Add query contract version * A few more asserts for balance * Make MigrateMsg a struct --------- Co-authored-by: mx <maxhampshire@pm.me> commit dd699bce9a Merge: 5ce017ef3 e6957e7a9 Author: Tommy Verrall <60836166+tommyv1987@users.noreply.github.com> Date: Wed Apr 5 10:18:16 2023 +0100 Merge pull request #3235 from nymtech/feature/performance-active-set-selection Feature/performance active set selection commit 5ce017ef3d Author: benedetta davico <46782255+benedettadavico@users.noreply.github.com> Date: Wed Apr 5 10:57:45 2023 +0200 adding vesting tests (#3279) commit 59c1ce2639 Merge: 4fb63d889 276edfd56 Author: Tommy Verrall <60836166+tommyv1987@users.noreply.github.com> Date: Wed Apr 5 09:50:53 2023 +0100 Merge pull request #3261 from nymtech/feature/refresh-allow-list Feature/refresh allow list commit 4fb63d8892 Author: Jędrzej Stuczyński <jedrzej.stuczynski@gmail.com> Date: Wed Apr 5 09:22:43 2023 +0100 Feature/vesting delegation amount query (#3229) * moved queries and transactions out of contract.rs * added queries for vesting delegation details * nyxd_client support commit 276edfd562 Author: Jędrzej Stuczyński <jedrzej.stuczynski@gmail.com> Date: Fri Mar 31 15:56:21 2023 +0100 clippy commit 605f8fcde3 Author: Jędrzej Stuczyński <jedrzej.stuczynski@gmail.com> Date: Fri Mar 31 15:06:12 2023 +0100 updated and cleaned up tests commit f0e4d1a7cf Author: Jędrzej Stuczyński <jedrzej.stuczynski@gmail.com> Date: Fri Mar 31 14:01:36 2023 +0100 configurable stored lists locations commit 055ec4bdd5 Author: Jędrzej Stuczyński <jedrzej.stuczynski@gmail.com> Date: Fri Mar 31 12:57:02 2023 +0100 updating stored allow list on file changes commit 5761f9ac7f Author: Jędrzej Stuczyński <jedrzej.stuczynski@gmail.com> Date: Fri Mar 31 12:15:45 2023 +0100 file watcher commit 32620fd55f Author: Jędrzej Stuczyński <jedrzej.stuczynski@gmail.com> Date: Thu Mar 30 17:47:12 2023 +0100 updating standard list in a timer commit abb5cdbe06 Author: Jędrzej Stuczyński <jedrzej.stuczynski@gmail.com> Date: Thu Mar 30 16:43:58 2023 +0100 extracted domain and ipnet information to separate struct commit e6957e7a99 Author: Jędrzej Stuczyński <jedrzej.stuczynski@gmail.com> Date: Tue Mar 28 11:25:43 2023 +0100 use combination of stake and performance for rewarded set selection commit de2406a2c7 Author: Jędrzej Stuczyński <jedrzej.stuczynski@gmail.com> Date: Tue Mar 28 10:54:14 2023 +0100 Moved MixnodeWithPerformance to helpers
2023-04-05 12:29:41 +02:00
parent 0b1b6947e8
commit 790e7a0e1e
12 changed files with 213 additions and 41 deletions
@@ -18,9 +18,23 @@ semver = "0.11"
 serde = { workspace = true, features = ["derive"], optional = true }
 serde_json = { workspace = true, optional = true }

+## tracing
+tracing-appender = { version = "0.2.2", optional = true }
+tracing-subscriber = { version = "0.3.16", features = [
+    "env-filter",
+], optional = true }
+tracing-tree = { version = "0.2.2", optional = true }
+
+
 [build-dependencies]
-vergen = { version = "=7.4.3", default-features = false, features = ["build", "git", "rustc", "cargo"] }
+vergen = { version = "=7.4.3", default-features = false, features = [
+    "build",
+    "git",
+    "rustc",
+    "cargo",
+] }

 [features]
 default = []
 output_format = ["serde", "serde_json"]
+tracing = ["tracing-appender", "tracing-subscriber", "tracing-tree"]
@@ -1,5 +1,16 @@
 // Copyright 2022 - Nym Technologies SA <contact@nymtech.net>
 // SPDX-License-Identifier: Apache-2.0
+// use tracing_subscriber::{
+//     fmt::Layer, layer::SubscriberExt, util::SubscriberInitExt, EnvFilter, Registry,
+// };
+// use tracing_tree::HierarchicalLayer;
+
+#[cfg(feature = "tracing")]
+pub use tracing_appender;
+#[cfg(feature = "tracing")]
+pub use tracing_subscriber;
+#[cfg(feature = "tracing")]
+pub use tracing_tree;

 // I'd argue we should start transitioning from `log` to `tracing`
 pub fn setup_logging() {
@@ -24,6 +35,34 @@ pub fn setup_logging() {
        .init();
 }

+// TODO: This has to be a macro, running it as a function does not work for the file_appender for some reason
+#[cfg(feature = "tracing")]
+#[macro_export]
+macro_rules! setup_tracing {
+    ($file_name: expr) => {
+        use nym_bin_common::logging::tracing_subscriber::layer::SubscriberExt;
+        use nym_bin_common::logging::tracing_subscriber::util::SubscriberInitExt;
+
+        let file_appender =
+            nym_bin_common::logging::tracing_appender::rolling::hourly($file_name, "log");
+        let (non_blocking, _guard) =
+            nym_bin_common::logging::tracing_appender::non_blocking(file_appender);
+        let appender_layer = nym_bin_common::logging::tracing_subscriber::fmt::Layer::new()
+            .with_ansi(false)
+            .with_writer(non_blocking);
+
+        nym_bin_common::logging::tracing_subscriber::Registry::default()
+            .with(nym_bin_common::logging::tracing_subscriber::EnvFilter::from_default_env())
+            .with(appender_layer)
+            .with(
+                nym_bin_common::logging::tracing_tree::HierarchicalLayer::new(4)
+                    .with_targets(true)
+                    .with_bracketed_fields(true),
+            )
+            .init();
+    };
+}
+
 pub fn banner(crate_name: &str, crate_version: &str) -> String {
    format!(
        r#"
@@ -13,12 +13,21 @@ humantime-serde = "1.0"
 log = { workspace = true }
 rand = "0.8"
 serde = { version = "1.0", features = ["derive"] }
-tokio = { version = "1.24.1", features = ["time", "macros", "rt", "net", "io-util"] }
+tokio = { version = "1.24.1", features = [
+    "time",
+    "macros",
+    "rt",
+    "net",
+    "io-util",
+] }
 tokio-util = { version = "0.7.4", features = ["codec"] }
 url = "2.2"
 thiserror = "1.0.37"

-nym-crypto =  { path = "../crypto" }
+## tracing
+tracing = { version = "0.1.37", optional = true }
+
+nym-crypto = { path = "../crypto" }
 nym-network-defaults = { path = "../network-defaults" }
 nym-sphinx-acknowledgements = { path = "../nymsphinx/acknowledgements" }
 nym-sphinx-addressing = { path = "../nymsphinx/addressing" }
@@ -27,5 +36,13 @@ nym-sphinx-framing = { path = "../nymsphinx/framing" }
 nym-sphinx-params = { path = "../nymsphinx/params" }
 nym-sphinx-types = { path = "../nymsphinx/types" }
 nym-task = { path = "../task" }
-validator-client = { path = "../client-libs/validator-client", features = ["nyxd-client"]}
+validator-client = { path = "../client-libs/validator-client", features = [
+    "nyxd-client",
+] }
 nym-bin-common = { path = "../bin-common" }
+
+cfg-if = "1.0.0"
+cpu-cycles = { path = "../../cpu-cycles", optional = true }
+
+[features]
+cpucycles = ["cpu-cycles", "tracing"]
@@ -1,5 +1,41 @@
 // Copyright 2021 - Nym Technologies SA <contact@nymtech.net>
 // SPDX-License-Identifier: Apache-2.0
-
 pub mod packet_processor;
 pub mod verloc;
+
+pub fn cpu_cycles() -> Result<i64, Box<dyn std::error::Error>> {
+    cfg_if::cfg_if! {
+        if #[cfg(feature = "cpucycles")] {
+            Ok(cpu_cycles::cpucycles()?)
+        } else {
+            Err("`cpucycles` feature is not turned on!".into())
+        }
+    }
+}
+
+#[macro_export]
+macro_rules! measure {
+    ( $x:expr ) => {{
+        cfg_if::cfg_if! {
+            if #[cfg(feature = "cpucycles")] {
+                let start_cycles = $crate::cpu_cycles();
+        // if the block needs to return something, we can return it
+        let r = $x;
+        let end_cycles = $crate::cpu_cycles();
+        let name = if let Some(meta) = tracing::Span::current().metadata() {
+            meta.name()
+        } else {
+            "measure"
+        };
+        match (start_cycles, end_cycles) {
+            (Ok(start), Ok(end)) => info!("{} cpucycles: {}", name, end - start),
+            (Err(e), _) => error!("{e}"),
+            (_, Err(e)) => error!("{e}"),
+        }
+        r
+            } else {
+                $x
+            }
+        }
+    }};
+}
@@ -1,6 +1,7 @@
 // Copyright 2021 - Nym Technologies SA <contact@nymtech.net>
 // SPDX-License-Identifier: Apache-2.0

+use crate::measure;
 use crate::packet_processor::error::MixProcessingError;
 use log::*;
 use nym_sphinx_acknowledgements::surb_ack::SurbAck;
@@ -14,6 +15,8 @@ use nym_sphinx_types::{
 };
 use std::convert::TryFrom;
 use std::sync::Arc;
+#[cfg(feature = "cpucycles")]
+use tracing::instrument;

 type ForwardAck = MixPacket;

@@ -46,29 +49,41 @@ impl SphinxPacketProcessor {
    }

    /// Performs a fresh sphinx unwrapping using no cache.
+    #[cfg_attr(
+        feature = "cpucycles",
+        instrument(skip(self, packet), fields(cpucycles))
+    )]
    fn perform_initial_sphinx_packet_processing(
        &self,
        packet: SphinxPacket,
    ) -> Result<ProcessedPacket, MixProcessingError> {
-        packet.process(&self.sphinx_key).map_err(|err| {
-            debug!("Failed to unwrap Sphinx packet: {err}");
-            MixProcessingError::SphinxProcessingError(err)
+        measure!({
+            packet.process(&self.sphinx_key).map_err(|err| {
+                debug!("Failed to unwrap Sphinx packet: {err}");
+                MixProcessingError::SphinxProcessingError(err)
+            })
        })
    }

    /// Takes the received framed packet and tries to unwrap it from the sphinx encryption.
+    #[cfg_attr(
+        feature = "cpucycles",
+        instrument(skip(self, received), fields(cpucycles))
+    )]
    fn perform_initial_unwrapping(
        &self,
        received: FramedSphinxPacket,
    ) -> Result<ProcessedPacket, MixProcessingError> {
-        let packet_mode = received.packet_mode();
-        let sphinx_packet = received.into_inner();
+        measure!({
+            let packet_mode = received.packet_mode();
+            let sphinx_packet = received.into_inner();

-        if packet_mode.is_old_vpn() {
-            return Err(MixProcessingError::ReceivedOldTypeVpnPacket);
-        }
+            if packet_mode.is_old_vpn() {
+                return Err(MixProcessingError::ReceivedOldTypeVpnPacket);
+            }

-        self.perform_initial_sphinx_packet_processing(sphinx_packet)
+            self.perform_initial_sphinx_packet_processing(sphinx_packet)
+        })
    }

    /// Processed received forward hop packet - tries to extract next hop address, sets delay
@@ -171,20 +186,26 @@ impl SphinxPacketProcessor {
        }
    }

+    #[cfg_attr(
+        feature = "cpucycles",
+        instrument(skip(self, received), fields(cpucycles))
+    )]
    pub fn process_received(
        &self,
        received: FramedSphinxPacket,
    ) -> Result<MixProcessingResult, MixProcessingError> {
        // explicit packet size will help to correctly parse final hop
-        let packet_size = received.packet_size();
-        let packet_mode = received.packet_mode();
+        measure!({
+            let packet_size = received.packet_size();
+            let packet_mode = received.packet_mode();

-        // unwrap the sphinx packet and if possible and appropriate, cache keys
-        let processed_packet = self.perform_initial_unwrapping(received)?;
+            // unwrap the sphinx packet and if possible and appropriate, cache keys
+            let processed_packet = self.perform_initial_unwrapping(received)?;

-        // for forward packets, extract next hop and set delay (but do NOT delay here)
-        // for final packets, extract SURBAck
-        self.perform_final_processing(processed_packet, packet_size, packet_mode)
+            // for forward packets, extract next hop and set delay (but do NOT delay here)
+            // for final packets, extract SURBAck
+            self.perform_final_processing(processed_packet, packet_size, packet_mode)
+        })
    }
 }

@@ -36,6 +36,12 @@ tokio = { version = "1.21.2", features = ["rt-multi-thread", "net", "signal"] }
 tokio-util = { version = "0.7.3", features = ["codec"] }
 toml = "0.5.8"
 url = { version = "2.2", features = ["serde"] }
+cfg-if = "1.0.0"
+
+## tracing
+tracing = { version = "0.1.37", optional = true }
+opentelemetry = { version = "0.19.0", optional = true }
+

 ## internal
 nym-config = { path = "../common/config" }
@@ -63,3 +69,11 @@ tokio = { version = "1.21.2", features = [

 nym-sphinx-types = { path = "../common/nymsphinx/types" }
 nym-sphinx-params = { path = "../common/nymsphinx/params" }
+
+[features]
+cpucycles = [
+    "mixnode-common/cpucycles",
+    "tracing",
+    "opentelemetry",
+    "nym-bin-common/tracing",
+]
@@ -8,11 +8,12 @@ use crate::config::{persistence::pathfinder::MixNodePathfinder, Config};
 use crate::node::MixNode;
 use anyhow::{bail, Result};
 use clap::{ArgGroup, Args};
-use log::error;
 use nym_bin_common::output_format::OutputFormat;
 use nym_config::NymConfig;
 use nym_crypto::asymmetric::identity;
 use nym_types::helpers::ConsoleSigningOutput;
+#[cfg(feature = "cpucycles")]
+use tracing::error;
 use validator_client::nyxd;

 use super::version_check;
@@ -7,9 +7,15 @@ extern crate rocket;
 use ::nym_config::defaults::setup_env;
 use clap::{crate_name, crate_version, Parser};
 use lazy_static::lazy_static;
+#[cfg(feature = "cpucycles")]
+use mixnode_common::measure;
 use nym_bin_common::build_information::BinaryBuildInformation;
+#[allow(unused_imports)]
 use nym_bin_common::logging::{maybe_print_banner, setup_logging};
-
+#[cfg(feature = "cpucycles")]
+use nym_bin_common::setup_tracing;
+#[cfg(feature = "cpucycles")]
+use tracing::instrument;
 mod commands;
 mod config;
 mod node;
@@ -35,19 +41,32 @@ struct Cli {
    command: commands::Commands,
 }

-#[cfg(feature = "cpu-cycles")]
-pub fn cpu_cycles() {
-    info!("{}", cpu_cycles::cpucycles())
+#[cfg(feature = "cpucycles")]
+#[instrument(fields(cpucycles))]
+fn test_function() {
+    measure!({})
 }

 #[tokio::main]
 async fn main() {
-    setup_logging();
+    cfg_if::cfg_if! {
+        if #[cfg(feature = "cpucycles")] {
+            setup_tracing!("/tmp/tracing.log");
+        } else {
+            setup_logging();
+        }
+    }
+
    maybe_print_banner(crate_name!(), crate_version!());

    let args = Cli::parse();
    setup_env(args.config_env_file.as_ref());
    commands::execute(args).await;
+
+    cfg_if::cfg_if! {
+    if #[cfg(feature = "cpucycles")] {
+        opentelemetry::global::shutdown_tracer_provider();
+    }}
 }

 #[cfg(test)]
@@ -7,7 +7,7 @@ use crate::node::listener::connection_handler::packet_processing::{
 use crate::node::packet_delayforwarder::PacketDelayForwardSender;
 use crate::node::TaskClient;
 use futures::StreamExt;
-use log::{error, info};
+use mixnode_common::measure;
 use nym_sphinx::forwarding::packet::MixPacket;
 use nym_sphinx::framing::codec::SphinxCodec;
 use nym_sphinx::framing::packet::FramedSphinxPacket;
@@ -16,6 +16,8 @@ use std::net::SocketAddr;
 use tokio::net::TcpStream;
 use tokio::time::Instant;
 use tokio_util::codec::Framed;
+#[cfg(feature = "cpucycles")]
+use tracing::{error, info, instrument};

 pub(crate) mod packet_processing;

@@ -48,6 +50,10 @@ impl ConnectionHandler {
            .expect("the delay-forwarder has died!");
    }

+    #[cfg_attr(
+        feature = "cpucycles",
+        instrument(skip(self, framed_sphinx_packet), fields(cpucycles))
+    )]
    fn handle_received_packet(&self, framed_sphinx_packet: FramedSphinxPacket) {
        //
        // TODO: here be replay attack detection - it will require similar key cache to the one in
@@ -57,17 +63,19 @@ impl ConnectionHandler {

        // all processing such, key caching, etc. was done.
        // however, if it was a forward hop, we still need to delay it
-        match self.packet_processor.process_received(framed_sphinx_packet) {
-            Err(err) => debug!("We failed to process received sphinx packet - {err}"),
-            Ok(res) => match res {
-                MixProcessingResult::ForwardHop(forward_packet, delay) => {
-                    self.delay_and_forward_packet(forward_packet, delay)
-                }
-                MixProcessingResult::FinalHop(..) => {
-                    warn!("Somehow processed a loop cover message that we haven't implemented yet!")
-                }
-            },
-        }
+        measure!({
+            match self.packet_processor.process_received(framed_sphinx_packet) {
+                Err(err) => debug!("We failed to process received sphinx packet - {err}"),
+                Ok(res) => match res {
+                    MixProcessingResult::ForwardHop(forward_packet, delay) => {
+                        self.delay_and_forward_packet(forward_packet, delay)
+                    }
+                    MixProcessingResult::FinalHop(..) => {
+                        warn!("Somehow processed a loop cover message that we haven't implemented yet!")
+                    }
+                },
+            }
+        })
    }

    pub(crate) async fn handle_connection(
@@ -2,11 +2,12 @@
 // SPDX-License-Identifier: Apache-2.0

 use crate::node::listener::connection_handler::ConnectionHandler;
-use log::error;
 use std::net::SocketAddr;
 use std::process;
 use tokio::net::TcpListener;
 use tokio::task::JoinHandle;
+#[cfg(feature = "cpucycles")]
+use tracing::error;

 use super::TaskClient;

@@ -16,7 +16,6 @@ use crate::node::listener::Listener;
 use crate::node::node_description::NodeDescription;
 use crate::node::node_statistics::SharedNodeStats;
 use crate::node::packet_delayforwarder::{DelayForwarder, PacketDelayForwardSender};
-use log::{error, info, warn};
 use mixnode_common::verloc::{self, AtomicVerlocResult, VerlocMeasurer};
 use nym_bin_common::output_format::OutputFormat;
 use nym_bin_common::version_checker::parse_version;
@@ -28,6 +27,8 @@ use rand::thread_rng;
 use std::net::SocketAddr;
 use std::process;
 use std::sync::Arc;
+#[cfg(feature = "cpucycles")]
+use tracing::{error, info, warn};

 mod http;
 mod listener;
@@ -3276,6 +3276,7 @@ dependencies = [
 name = "nym-bin-common"
 version = "0.3.0"
 dependencies = [
+ "atty",
 "clap",
 "clap_complete",
 "clap_complete_fig",