POC measurement

common/bin-common/Cargo.toml

@@ -18,8 +18,18 @@ semver = "0.11"
 serde = { workspace = true, features = ["derive"], optional = true }
 serde_json = { workspace = true, optional = true }
 
+## tracing
+tracing-appender = "0.2.2"
+tracing-subscriber = { version = "0.3.16", features = ["env-filter"] }
+
+
 [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 = []

common/bin-common/src/logging/mod.rs

@@ -1,6 +1,10 @@
 // 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,
+};
+
 // I'd argue we should start transitioning from `log` to `tracing`
 pub fn setup_logging() {
     let mut log_builder = pretty_env_logger::formatted_timed_builder();
@@ -24,6 +28,18 @@ pub fn setup_logging() {
         .init();
 }
 
+pub fn setup_tracing(file_name: &str) {
+    let file_appender = tracing_appender::rolling::hourly(file_name, "log");
+    let (non_blocking, _guard) = tracing_appender::non_blocking(file_appender);
+    let appender_layer = Layer::new().with_writer(non_blocking);
+
+    let registry = Registry::default()
+        .with(EnvFilter::from_default_env())
+        .with(appender_layer);
+
+    registry.init();
+}
+
 pub fn banner(crate_name: &str, crate_version: &str) -> String {
     format!(
         r#"

mixnode/Cargo.toml

@@ -37,6 +37,9 @@ tokio-util = { version = "0.7.3", features = ["codec"] }
 toml = "0.5.8"
 url = { version = "2.2", features = ["serde"] }
 
+## tracing
+tracing = "0.1.37"
+
 ## internal
 nym-config = { path = "../common/config" }
 nym-crypto = { path = "../common/crypto" }

mixnode/src/main.rs

@@ -8,7 +8,7 @@ use ::nym_config::defaults::setup_env;
 use clap::{crate_name, crate_version, Parser};
 use lazy_static::lazy_static;
 use nym_bin_common::build_information::BinaryBuildInformation;
-use nym_bin_common::logging::{maybe_print_banner, setup_logging};
+use nym_bin_common::logging::{maybe_print_banner, setup_logging, setup_tracing};
 
 mod commands;
 mod config;
@@ -36,13 +36,29 @@ struct Cli {
 }
 
 #[cfg(feature = "cpu-cycles")]
-pub fn cpu_cycles() {
-    info!("{}", cpu_cycles::cpucycles())
+pub fn cpu_cycles() -> i64 {
+    cpu_cycles::cpucycles().unwrap_or(0)
+}
+
+pub fn cpu_cycles() -> i64 {
+    0
+}
+
+#[macro_export]
+macro_rules! measure {
+    ( $x:expr ) => {{
+        let start_cycles = $crate::cpu_cycles();
+        $x;
+        let end_cycles = $crate::cpu_cycles();
+        tracing::Span::current().record("cpucycles", end_cycles - start_cycles);
+    }};
 }
 
 #[tokio::main]
 async fn main() {
     setup_logging();
+    setup_tracing("/tmp/tracing.log");
+
     maybe_print_banner(crate_name!(), crate_version!());
 
     let args = Cli::parse();

mixnode/src/node/listener/connection_handler/mod.rs

@@ -16,6 +16,7 @@ use std::net::SocketAddr;
 use tokio::net::TcpStream;
 use tokio::time::Instant;
 use tokio_util::codec::Framed;
+use tracing::instrument;
 
 pub(crate) mod packet_processing;
 
@@ -48,6 +49,7 @@ impl ConnectionHandler {
             .expect("the delay-forwarder has died!");
     }
 
+    #[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,16 +59,18 @@ 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!")
-                }
-            },
+        crate::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!")
+                    }
+                },
+            }
         }
     }