Add tracing setup (#108)

Author: maciektr

Cargo.lock

@@ -19,6 +19,10 @@ serde_json = "1.0.145"
 clap = "4.5.48"
 anyhow = "1.0.100"
 console = "0.16.1"
+tracing =  "0.1"
+chrono = { version = "0.4", optional = true }
+tracing-chrome = {version = "0.7", optional = true}
+tracing-subscriber = { version = "0.3", optional = true, features = ["env-filter"] }
 
 [dev-dependencies]
 snapbox = "0.6.21"
@@ -28,3 +32,6 @@ fs_extra = "1.3.0"
 test-case = "3.3.1"
 num-bigint = "0.4.6"
 cairo-lang-casm = { version = "2.12.3", features = ["serde"] }
+
+[features]
+tracing = ["dep:chrono", "dep:tracing-chrome", "dep:tracing-subscriber"]

Cargo.toml

@@ -23,6 +23,7 @@ pub struct CompileContract {
 }
 
 /// Compiles Sierra of the Starknet contract.
+#[tracing::instrument(skip_all, level = "info")]
 pub fn compile(mut sierra_json: Value) -> Result<Value> {
     sierra_json["abi"] = Value::Null;
     sierra_json["sierra_program_debug_info"] = Value::Null;

src/commands/compile_contract.rs

@@ -5,6 +5,7 @@ use cairo_lang_sierra_to_casm::metadata::{calc_metadata, MetadataComputationConf
 use clap::Args;
 use serde_json::{json, Value};
 use std::path::PathBuf;
+use tracing::trace_span;
 
 #[derive(Args)]
 pub struct CompileRaw {
@@ -20,29 +21,51 @@ pub struct CompileRaw {
 }
 
 /// Compiles Sierra of the plain Cairo code.
+#[tracing::instrument(skip_all, level = "info")]
 pub fn compile(sierra_program: Value) -> Result<Value> {
-    let sierra_program: Program = serde_json::from_value(sierra_program)
-        .context("Unable to deserialize Sierra program. Make sure it is in a correct format")?;
+    let span = trace_span!("deserialize_sierra");
+    let sierra_program: Program = {
+        let _g = span.enter();
+        serde_json::from_value(sierra_program)
+            .context("Unable to deserialize Sierra program. Make sure it is in a correct format")?
+    };
+
     let metadata_config = MetadataComputationConfig::default();
-    let metadata = calc_metadata(&sierra_program, metadata_config)?;
+    let span = trace_span!("calc_metadata");
+    let metadata = {
+        let _g = span.enter();
+        calc_metadata(&sierra_program, metadata_config)?
+    };
 
-    let cairo_program = cairo_lang_sierra_to_casm::compiler::compile(
-        &sierra_program,
-        &metadata,
-        SierraToCasmConfig {
-            gas_usage_check: true,
-            max_bytecode_size: usize::MAX,
-        },
-    )?;
-    let assembled_cairo_program = cairo_program.assemble();
+    let span = trace_span!("compile_sierra_to_casm");
+    let cairo_program = {
+        let _g = span.enter();
+        cairo_lang_sierra_to_casm::compiler::compile(
+            &sierra_program,
+            &metadata,
+            SierraToCasmConfig {
+                gas_usage_check: true,
+                max_bytecode_size: usize::MAX,
+            },
+        )?
+    };
+    let span = trace_span!("assemble_cairo_program");
+    let assembled_cairo_program = {
+        let _g = span.enter();
+        cairo_program.assemble()
+    };
 
-    Ok(json!({
-        "assembled_cairo_program": {
-            "bytecode": serde_json::to_value(assembled_cairo_program.bytecode)?,
-            "hints": serde_json::to_value(assembled_cairo_program.hints)?
-        },
-        "debug_info": serde_json::to_value(serialize_cairo_program_debug_info(&cairo_program.debug_info))?
-    }))
+    let span = trace_span!("serialize_result");
+    Ok({
+        let _g = span.enter();
+        json!({
+            "assembled_cairo_program": {
+                "bytecode": serde_json::to_value(assembled_cairo_program.bytecode)?,
+                "hints": serde_json::to_value(assembled_cairo_program.hints)?
+            },
+            "debug_info": serde_json::to_value(serialize_cairo_program_debug_info(&cairo_program.debug_info))?
+        })
+    })
 }
 
 fn serialize_cairo_program_debug_info(debug_info: &CairoProgramDebugInfo) -> Vec<(usize, usize)> {

src/commands/compile_raw.rs

@@ -32,13 +32,15 @@ fn print_error_message(error: &Error) {
     eprintln!("[{error_tag}] {error}");
 }
 
+#[tracing::instrument(skip_all, level = "info")]
 fn read_json(file_path: PathBuf) -> Result<Value> {
     let sierra_file = File::open(file_path).context("Unable to open json file")?;
     let sierra_file_reader = BufReader::new(sierra_file);
 
     serde_json::from_reader(sierra_file_reader).context("Unable to read json file")
 }
 
+#[tracing::instrument(skip_all, level = "info")]
 fn output_casm(output_json: &Value, output_file_path: Option<PathBuf>) -> Result<()> {
     match output_file_path {
         Some(output_path) => {
@@ -58,6 +60,7 @@ fn output_casm(output_json: &Value, output_file_path: Option<PathBuf>) -> Result
 
 fn main_execution() -> Result<bool> {
     let cli = Cli::parse();
+    let _g = init_logging();
 
     match cli.command {
         Commands::CompileContract(compile_contract) => {
@@ -89,3 +92,96 @@ fn main() {
         }
     };
 }
+
+#[cfg(not(feature = "tracing"))]
+fn init_logging() -> Option<impl Drop> {
+    struct Zst;
+    impl Drop for Zst {
+        fn drop(&mut self) {}
+    }
+    Option::<Zst>::None
+}
+
+#[cfg(feature = "tracing")]
+fn init_logging() -> Option<impl Drop> {
+    use chrono::Local;
+    use std::fs;
+
+    use std::path::PathBuf;
+    use tracing_chrome::ChromeLayerBuilder;
+    use tracing_subscriber::filter::{EnvFilter, LevelFilter, Targets};
+    use tracing_subscriber::fmt::time::Uptime;
+    use tracing_subscriber::fmt::Layer;
+    use tracing_subscriber::prelude::*;
+
+    let mut guard = None;
+
+    let fmt_layer = Layer::new()
+        .with_writer(std::io::stderr)
+        .with_timer(Uptime::default())
+        .with_filter(
+            EnvFilter::builder()
+                .with_default_directive(LevelFilter::TRACE.into())
+                .with_env_var("USC_LOG")
+                .from_env_lossy(),
+        );
+
+    // Disabled unless explicitly enabled with env var.
+    let tracing_profile = is_truthy_env("USC_TRACING_PROFILE", false);
+
+    let profile_layer = if tracing_profile {
+        let mut path = PathBuf::from(format!("./usc-profile-{}.json", Local::now().to_rfc3339()));
+
+        // Create the file now, so that we early panic, and `fs::canonicalize` will work.
+        let profile_file = fs::File::create(&path).expect("failed to create profile file");
+
+        // Try to canonicalise the path so that it is easier to find the file from logs.
+        if let Ok(canonical) = fs::canonicalize(&path) {
+            path = canonical;
+        }
+
+        eprintln!(
+            "this USC run will output tracing profile to: {}",
+            path.display()
+        );
+        eprintln!(
+            "open that file with https://ui.perfetto.dev (or chrome://tracing) to analyze it"
+        );
+
+        let (profile_layer, profile_layer_guard) = ChromeLayerBuilder::new()
+            .writer(profile_file)
+            .include_args(true)
+            .build();
+
+        // Filter out less important logs because they're too verbose,
+        // and with them the profile file quickly grows to several GBs of data.
+        let profile_layer = profile_layer.with_filter(
+            Targets::new()
+                .with_default(LevelFilter::TRACE)
+                .with_target("salsa", LevelFilter::WARN),
+        );
+
+        guard = Some(profile_layer_guard);
+        Some(profile_layer)
+    } else {
+        None
+    };
+
+    tracing::subscriber::set_global_default(
+        tracing_subscriber::registry()
+            .with(fmt_layer)
+            .with(profile_layer),
+    )
+    .expect("could not set up global logger");
+
+    guard
+}
+
+#[cfg(feature = "tracing")]
+#[must_use]
+pub fn is_truthy_env(name: &str, default: bool) -> bool {
+    std::env::var(name).ok().map_or(default, |var| {
+        let s = var.as_str();
+        s == "true" || s == "1"
+    })
+}