From 124e02641c5a53325de6af93ad7284641b471d10 Mon Sep 17 00:00:00 2001 From: Andrey Khmuro Date: Wed, 1 Nov 2023 09:38:07 +0100 Subject: [PATCH] feat: add Tracing logger to the VM --- CHANGELOG.md | 1 + assembly/Cargo.toml | 3 +- assembly/src/assembler/mod.rs | 6 +++ assembly/src/ast/mod.rs | 18 ++++++++- assembly/src/ast/module.rs | 6 +++ assembly/src/ast/program.rs | 11 +++++- assembly/src/library/masl.rs | 3 ++ assembly/src/library/path.rs | 5 +++ docs/src/intro/usage.md | 7 ++++ miden/Cargo.toml | 9 +++-- miden/src/cli/data.rs | 60 ++++++++++++++--------------- miden/src/cli/debug/mod.rs | 2 +- miden/src/cli/prove.rs | 48 ++++++++++++----------- miden/src/cli/run.rs | 72 +++++++++++++++++++++-------------- miden/src/cli/verify.rs | 7 ++-- miden/src/examples/mod.rs | 8 +--- miden/src/main.rs | 13 +++++++ processor/Cargo.toml | 4 +- processor/src/lib.rs | 1 + prover/Cargo.toml | 4 +- prover/src/gpu.rs | 13 ++++--- prover/src/lib.rs | 8 ++-- verifier/Cargo.toml | 3 +- verifier/src/lib.rs | 1 + 24 files changed, 197 insertions(+), 116 deletions(-) diff --git a/CHANGELOG.md b/CHANGELOG.md index e7930ce653..4e19b68ef3 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -18,6 +18,7 @@ - Introduced the `Event` decorator and an associated `on_event` handler on the `Host` trait (#1119). - Updated Winterfell dependency to v0.7 (#1121). - Added methods `StackOutputs::get_stack_item()` and `StackOutputs::get_stack_word()` (#1155). +- Added [Tracing](https://crates.io/crates/tracing) logger to the VM (#1139). #### CLI - Introduced the `!use` command for the Miden REPL (#1162). diff --git a/assembly/Cargo.toml b/assembly/Cargo.toml index 34e54d669a..e840292956 100644 --- a/assembly/Cargo.toml +++ b/assembly/Cargo.toml @@ -18,8 +18,9 @@ doctest = false [features] default = ["std"] -std = ["vm-core/std"] +std = ["vm-core/std", "tracing/attributes"] [dependencies] num_enum = "0.7" +tracing = { version = "0.1", default-features = false, optional = true } vm-core = { package = "miden-core", path = "../core", version = "0.8", default-features = false } diff --git a/assembly/src/assembler/mod.rs b/assembly/src/assembler/mod.rs index 0f8d2bcbcf..07469f848a 100644 --- a/assembly/src/assembler/mod.rs +++ b/assembly/src/assembler/mod.rs @@ -1,3 +1,5 @@ +#[cfg(feature = "std")] +use super::ast::instrument; use super::{ ast::{Instruction, ModuleAst, Node, ProcedureAst, ProgramAst}, btree_map, @@ -139,6 +141,7 @@ impl Assembler { /// /// # Errors /// Returns an error if the compilation of the specified program fails. + #[cfg_attr(feature = "std", instrument("Compile AST", skip_all))] pub fn compile_ast(&self, program: &ProgramAst) -> Result { // compile the program let mut context = AssemblyContext::for_program(Some(program)); @@ -194,6 +197,9 @@ impl Assembler { /// - If a module with the same path already exists in the module stack of the /// [AssemblyContext]. /// - If a lock to the [ProcedureCache] can not be attained. + #[cfg_attr(feature = "std", instrument(level = "trace", + name = "Compiling module", + fields(module = path.unwrap_or(&LibraryPath::anon_path()).path()), skip_all))] pub fn compile_module( &self, module: &ModuleAst, diff --git a/assembly/src/ast/mod.rs b/assembly/src/ast/mod.rs index bccfcc1d32..7c87927316 100644 --- a/assembly/src/ast/mod.rs +++ b/assembly/src/ast/mod.rs @@ -2,7 +2,6 @@ //! //! Structs in this module (specifically [ProgramAst] and [ModuleAst]) can be used to parse source //! code into relevant ASTs. This can be done via their `parse()` methods. - use super::{ crypto::hash::RpoDigest, BTreeMap, ByteReader, ByteWriter, Deserializable, DeserializationError, Felt, LabelError, LibraryPath, ParsingError, ProcedureId, ProcedureName, @@ -11,6 +10,9 @@ use super::{ }; use vm_core::utils::bound_into_included_u64; +#[cfg(feature = "std")] +pub use tracing::{event, info_span, instrument, Level}; + pub use super::tokens::SourceLocation; mod nodes; @@ -91,3 +93,17 @@ fn sort_procs_into_vec(proc_map: LocalProcMap) -> Vec { procedures.into_iter().map(|(_idx, proc)| proc).collect() } + +/// Logging a warning message for every imported but unused module. +#[cfg(feature = "std")] +fn check_unused_imports(import_info: &ModuleImports) { + let import_lib_paths = import_info.import_paths(); + let invoked_procs_paths: Vec<&LibraryPath> = + import_info.invoked_procs().iter().map(|(_id, (_name, path))| path).collect(); + + for lib in import_lib_paths { + if !invoked_procs_paths.contains(&lib) { + event!(Level::WARN, "unused import: \"{}\"", lib); + } + } +} diff --git a/assembly/src/ast/module.rs b/assembly/src/ast/module.rs index 661e170fb9..669417b0a2 100644 --- a/assembly/src/ast/module.rs +++ b/assembly/src/ast/module.rs @@ -1,3 +1,5 @@ +#[cfg(feature = "std")] +use super::check_unused_imports; use super::{ format::*, imports::ModuleImports, @@ -10,6 +12,7 @@ use super::{ String, ToString, Token, TokenStream, Vec, }, }; + use core::{fmt, str::from_utf8}; use vm_core::utils::Serializable; @@ -107,6 +110,9 @@ impl ModuleAst { // get module docs and make sure the size is within the limit let docs = tokens.take_module_comments(); + #[cfg(feature = "std")] + check_unused_imports(context.import_info); + Ok(Self::new(local_procs, reexported_procs, docs)?.with_import_info(import_info)) } diff --git a/assembly/src/ast/program.rs b/assembly/src/ast/program.rs index 0843bb29e2..001f5ddbab 100644 --- a/assembly/src/ast/program.rs +++ b/assembly/src/ast/program.rs @@ -16,10 +16,13 @@ use super::{ SliceReader, Token, TokenStream, Vec, }, }; + use core::{fmt, iter}; #[cfg(feature = "std")] -use std::{fs, io, path::Path}; - +use { + super::{check_unused_imports, instrument}, + std::{fs, io, path::Path}, +}; // PROGRAM AST // ================================================================================================ @@ -120,6 +123,7 @@ impl ProgramAst { /// Parses the provided source into a [ProgramAst]. /// /// A program consist of a body and a set of internal (i.e., not exported) procedures. + #[cfg_attr(feature = "std", instrument(name = "Parsing program", skip_all))] pub fn parse(source: &str) -> Result { let mut tokens = TokenStream::new(source)?; let mut import_info = ModuleImports::parse(&mut tokens)?; @@ -178,6 +182,9 @@ impl ProgramAst { return Err(ParsingError::dangling_ops_after_program(token)); } + #[cfg(feature = "std")] + check_unused_imports(context.import_info); + let local_procs = sort_procs_into_vec(context.local_procs); let (nodes, locations) = body.into_parts(); Ok(Self::new(nodes, local_procs)? diff --git a/assembly/src/library/masl.rs b/assembly/src/library/masl.rs index f02d813f7b..bc2d95735f 100644 --- a/assembly/src/library/masl.rs +++ b/assembly/src/library/masl.rs @@ -1,3 +1,5 @@ +#[cfg(feature = "std")] +use super::super::ast::instrument; use super::{ super::BTreeSet, AstSerdeOptions, ByteReader, ByteWriter, Deserializable, DeserializationError, Library, LibraryError, LibraryNamespace, LibraryPath, Module, ModuleAst, Serializable, Vec, @@ -184,6 +186,7 @@ mod use_std { } /// Read a library from a file. + #[instrument(name = "Reading library file", fields(path = %path.as_ref().display()))] pub fn read_from_file

(path: P) -> Result where P: AsRef, diff --git a/assembly/src/library/path.rs b/assembly/src/library/path.rs index 600d81d435..d3c28c8285 100644 --- a/assembly/src/library/path.rs +++ b/assembly/src/library/path.rs @@ -86,6 +86,11 @@ impl LibraryPath { // PUBLIC ACCESSORS // -------------------------------------------------------------------------------------------- + /// Returns the full path of the Library + pub fn path(&self) -> &str { + &self.path + } + /// Returns the first component of the path. /// /// The first component is the leftmost token separated by `::`. diff --git a/docs/src/intro/usage.md b/docs/src/intro/usage.md index 96a9b120d1..10baae805e 100644 --- a/docs/src/intro/usage.md +++ b/docs/src/intro/usage.md @@ -85,6 +85,13 @@ For example: To execute a program using the Miden VM there needs to be a `.masm` file containing the Miden Assembly code and a `.inputs` file containing the inputs. +#### Enabling logging +You can use `MIDEN_LOG` environment variable to control how much logging output the VM produces. For example: +``` +MIDEN_LOG=trace ./target/optimized/miden [subcommand] [parameters] +``` +If the level is not specified, `warn` level is set as default. + ### Inputs As described [here](https://0xpolygonmiden.github.io/miden-vm/intro/overview.html#inputs-and-outputs) the Miden VM can consume public and secret inputs. diff --git a/miden/Cargo.toml b/miden/Cargo.toml index f0e8b85389..99c9f34165 100644 --- a/miden/Cargo.toml +++ b/miden/Cargo.toml @@ -40,17 +40,15 @@ path = "tests/integration/main.rs" [features] concurrent = ["prover/concurrent", "std"] default = ["std"] -executable = ["dep:env_logger", "dep:hex", "hex?/std", "std", "dep:serde", "serde?/std", "dep:serde_derive", "dep:serde_json", "serde_json?/std", "dep:clap", "dep:rustyline"] +executable = ["dep:hex", "hex?/std", "std", "dep:serde", "serde?/std", "dep:serde_derive", "dep:serde_json", "serde_json?/std", "dep:clap", "dep:rustyline"] metal = ["prover/metal", "std"] -std = ["assembly/std", "log/std", "processor/std", "prover/std", "verifier/std"] +std = ["assembly/std", "processor/std", "prover/std", "tracing/attributes", "verifier/std"] [dependencies] assembly = { package = "miden-assembly", path = "../assembly", version = "0.8", default-features = false } blake3 = "1.5" clap = { version = "4.4", features = ["derive"], optional = true } -env_logger = { version = "0.10", default-features = false, optional = true } hex = { version = "0.4", optional = true } -log = { version = "0.4", default-features = false, optional = true } processor = { package = "miden-processor", path = "../processor", version = "0.8", default-features = false } prover = { package = "miden-prover", path = "../prover", version = "0.8", default-features = false } rustyline = { version = "13.0", default-features = false, optional = true } @@ -58,6 +56,9 @@ serde = {version = "1.0", optional = true } serde_derive = {version = "1.0", optional = true } serde_json = {version = "1.0", optional = true } stdlib = { package = "miden-stdlib", path = "../stdlib", version = "0.8", default-features = false } +tracing = { version = "0.1", default-features = false, optional = true } +tracing-subscriber = { version = "0.3", features = ["std", "env-filter"] } +tracing-forest = { version = "0.1", features = ["ansi", "smallvec"] } verifier = { package = "miden-verifier", path = "../verifier", version = "0.8", default-features = false } vm-core = { package = "miden-core", path = "../core", version = "0.8", default-features = false } diff --git a/miden/src/cli/data.rs b/miden/src/cli/data.rs index aef6b6b691..444f3dd772 100644 --- a/miden/src/cli/data.rs +++ b/miden/src/cli/data.rs @@ -12,9 +12,9 @@ use std::{ fs, io::Write, path::{Path, PathBuf}, - time::Instant, }; use stdlib::StdLibrary; +pub use tracing::{event, info_span, instrument, trace_span, Level}; // HELPERS // ================================================================================================ @@ -81,6 +81,7 @@ pub struct InputFile { /// Helper methods to interact with the input file impl InputFile { + #[instrument(name = "Reading input file", skip_all)] pub fn read(inputs_path: &Option, program_path: &Path) -> Result { // if file not specified explicitly and corresponding file with same name as program_path // with '.inputs' extension does't exist, set operand_stack to empty vector @@ -100,8 +101,6 @@ impl InputFile { None => program_path.with_extension("inputs"), }; - println!("Reading input file `{}`", path.display()); - // read input file to string let inputs_file = fs::read_to_string(&path) .map_err(|err| format!("Failed to open input file `{}` - {}", path.display(), err))?; @@ -199,14 +198,19 @@ impl InputFile { let tree = MerkleTree::new(leaves) .map_err(|e| format!("failed to parse a Merkle tree: {e}"))?; merkle_store.extend(tree.inner_nodes()); - println!("Added Merkle tree with root {} to the Merkle store", tree.root()); + event!( + Level::TRACE, + "Added Merkle tree with root {} to the Merkle store", + tree.root() + ); } MerkleData::SparseMerkleTree(data) => { let entries = Self::parse_sparse_merkle_tree(data)?; let tree = SimpleSmt::with_leaves(u64::BITS as u8, entries) .map_err(|e| format!("failed to parse a Sparse Merkle Tree: {e}"))?; merkle_store.extend(tree.inner_nodes()); - println!( + event!( + Level::TRACE, "Added Sparse Merkle tree with root {} to the Merkle store", tree.root() ); @@ -216,7 +220,8 @@ impl InputFile { let tree = PartialMerkleTree::with_leaves(entries) .map_err(|e| format!("failed to parse a Partial Merkle Tree: {e}"))?; merkle_store.extend(tree.inner_nodes()); - println!( + event!( + Level::TRACE, "Added Partial Merkle tree with root {} to the Merkle store", tree.root() ); @@ -316,6 +321,8 @@ impl OutputFile { } /// Read the output file + #[instrument(name = "Reading output file", + fields(path = %outputs_path.clone().unwrap_or(program_path.with_extension("outputs")).display()), skip_all)] pub fn read(outputs_path: &Option, program_path: &Path) -> Result { // If outputs_path has been provided then use this as path. Alternatively we will // replace the program_path extension with `.outputs` and use this as a default. @@ -324,8 +331,6 @@ impl OutputFile { None => program_path.with_extension("outputs"), }; - println!("Reading output file `{}`", path.display()); - // read outputs file to string let outputs_file = fs::read_to_string(&path) .map_err(|err| format!("Failed to open outputs file `{}` - {}", path.display(), err))?; @@ -338,16 +343,13 @@ impl OutputFile { } /// Write the output file + #[instrument(name = "Writing data to output file", fields(path = %path.display()), skip_all)] pub fn write(stack_outputs: &StackOutputs, path: &PathBuf) -> Result<(), String> { // if path provided, create output file - println!("Creating output file `{}`", path.display()); - let file = fs::File::create(&path).map_err(|err| { format!("Failed to create output file `{}` - {}", path.display(), err) })?; - println!("Writing data to output file"); - // write outputs to output file serde_json::to_writer_pretty(file, &Self::new(stack_outputs)) .map_err(|err| format!("Failed to write output data - {}", err)) @@ -379,19 +381,17 @@ pub struct ProgramFile { /// Helper methods to interact with masm program file. impl ProgramFile { /// Reads the masm file at the specified path and parses it into a [ProgramAst]. + #[instrument(name = "Reading program file", fields(path = %path.display()))] pub fn read(path: &PathBuf) -> Result { // read program file to string - println!("Reading program file `{}`", path.display()); - let source = fs::read_to_string(&path) - .map_err(|err| format!("Failed to open program file `{}` - {}", path.display(), err))?; + let source = fs::read_to_string(&path).map_err(|err| { + format!("Failed to open program file `{}` - {}\n", path.display(), err) + })?; // parse the program into an AST - print!("Parsing program... "); - let now = Instant::now(); let ast = ProgramAst::parse(&source).map_err(|err| { - format!("Failed to parse program file `{}` - {}", path.display(), err) + format!("Failed to parse program file `{}` - {}\n", path.display(), err) })?; - println!("done ({} ms)", now.elapsed().as_millis()); Ok(Self { ast, @@ -400,14 +400,12 @@ impl ProgramFile { } /// Compiles this program file into a [Program]. + #[instrument(name = "Compiling program", skip_all)] pub fn compile(&self, debug: &Debug, libraries: I) -> Result where I: IntoIterator, L: Library, { - print!("Compiling program... "); - let now = Instant::now(); - // compile program let mut assembler = Assembler::default() .with_debug_mode(debug.is_on()) @@ -422,8 +420,6 @@ impl ProgramFile { .compile_ast(&self.ast) .map_err(|err| format!("Failed to compile program - {}", err))?; - println!("done ({} ms)", now.elapsed().as_millis()); - Ok(program) } @@ -450,6 +446,8 @@ pub struct ProofFile; /// Helper methods to interact with proof file impl ProofFile { /// Read stark proof from file + #[instrument(name = "Reading proof file", + fields(path = %proof_path.clone().unwrap_or(program_path.with_extension("proof")).display()), skip_all)] pub fn read( proof_path: &Option, program_path: &Path, @@ -461,8 +459,6 @@ impl ProofFile { None => program_path.with_extension("proof"), }; - println!("Reading proof file `{}`", path.display()); - // read the file to bytes let file = fs::read(&path) .map_err(|err| format!("Failed to open proof file `{}` - {}", path.display(), err))?; @@ -473,6 +469,10 @@ impl ProofFile { } /// Write stark proof to file + #[instrument(name = "Writing data to proof file", + fields( + path = %proof_path.clone().unwrap_or(program_path.with_extension("proof")).display(), + size = format!("{} KB", proof.to_bytes().len() / 1024)), skip_all)] pub fn write( proof: ExecutionProof, proof_path: &Option, @@ -485,16 +485,12 @@ impl ProofFile { None => program_path.with_extension("proof"), }; - println!("Creating proof file `{}`", path.display()); - // create output fille let mut file = fs::File::create(&path) .map_err(|err| format!("Failed to create proof file `{}` - {}", path.display(), err))?; let proof_bytes = proof.to_bytes(); - println!("Writing data to proof file - size {} KB", proof_bytes.len() / 1024); - // write proof bytes to file file.write_all(&proof_bytes).unwrap(); @@ -509,6 +505,7 @@ pub struct ProgramHash; /// Helper method to parse program hash from hex impl ProgramHash { + #[instrument(name = "Reading program hash", skip_all)] pub fn read(hash_hex_string: &String) -> Result { // decode hex to bytes let program_hash_bytes = hex::decode(hash_hex_string) @@ -533,6 +530,7 @@ pub struct Libraries { impl Libraries { /// Creates a new instance of [Libraries] from a list of library paths. + #[instrument(name = "Reading library files", skip_all)] pub fn new(paths: I) -> Result where P: AsRef, @@ -541,8 +539,6 @@ impl Libraries { let mut libraries = Vec::new(); for path in paths { - println!("Reading library file `{}`", path.as_ref().display()); - let library = MaslLibrary::read_from_file(path) .map_err(|e| format!("Failed to read library: {e}"))?; libraries.push(library); diff --git a/miden/src/cli/debug/mod.rs b/miden/src/cli/debug/mod.rs index bd683fde29..16f71ab79a 100644 --- a/miden/src/cli/debug/mod.rs +++ b/miden/src/cli/debug/mod.rs @@ -40,7 +40,7 @@ impl DebugCmd { ProgramFile::read(&self.assembly_file)?.compile(&Debug::On, libraries.libraries)?; let program_hash: [u8; 32] = program.hash().into(); - println!("Debugging program with hash {}... ", hex::encode(program_hash)); + println!("Debugging program with hash {}...", hex::encode(program_hash)); // load input data from file let input_data = InputFile::read(&self.input_file, &self.assembly_file)?; diff --git a/miden/src/cli/prove.rs b/miden/src/cli/prove.rs index eb9b7d8d33..2555f37355 100644 --- a/miden/src/cli/prove.rs +++ b/miden/src/cli/prove.rs @@ -1,10 +1,10 @@ -use super::data::{Debug, InputFile, Libraries, OutputFile, ProgramFile, ProofFile}; +use super::data::{instrument, Debug, InputFile, Libraries, OutputFile, ProgramFile, ProofFile}; use clap::Parser; use miden::ProvingOptions; -use processor::{DefaultHost, ExecutionOptions, ExecutionOptionsError}; -use std::{io::Write, path::PathBuf, time::Instant}; +use processor::{DefaultHost, ExecutionOptions, ExecutionOptionsError, Program}; + +use std::{path::PathBuf, time::Instant}; -// TODO check if clap is supporting automatic generation of list values of hash function #[derive(Debug, Clone, Parser)] #[clap(about = "Prove a miden program")] pub struct ProveCmd { @@ -61,25 +61,11 @@ impl ProveCmd { } pub fn execute(&self) -> Result<(), String> { - println!("============================================================"); - println!("Prove program"); - println!("============================================================"); - - // configure logging - env_logger::Builder::new() - .format(|buf, record| writeln!(buf, "{}", record.args())) - .filter_level(log::LevelFilter::Debug) - .init(); - - // load libraries from files - let libraries = Libraries::new(&self.library_paths)?; + println!("==============================================================================="); + println!("Prove program: {}", self.assembly_file.display()); + println!("-------------------------------------------------------------------------------"); - // load program from file and compile - let program = - ProgramFile::read(&self.assembly_file)?.compile(&Debug::Off, libraries.libraries)?; - - // load input data from file - let input_data = InputFile::read(&self.input_file, &self.assembly_file)?; + let (program, input_data) = load_data(&self)?; let program_hash: [u8; 32] = program.hash().into(); println!("Proving program with hash {}...", hex::encode(program_hash)); @@ -123,3 +109,21 @@ impl ProveCmd { Ok(()) } } + +// HELPER FUNCTIONS +// ================================================================================================ + +#[instrument(skip_all)] +fn load_data(params: &ProveCmd) -> Result<(Program, InputFile), String> { + // load libraries from files + let libraries = Libraries::new(¶ms.library_paths)?; + + // load program from file and compile + let program = + ProgramFile::read(¶ms.assembly_file)?.compile(&Debug::Off, libraries.libraries)?; + + // load input data from file + let input_data = InputFile::read(¶ms.input_file, ¶ms.assembly_file)?; + + Ok((program, input_data)) +} diff --git a/miden/src/cli/run.rs b/miden/src/cli/run.rs index f123093dd2..08f3f9d86f 100644 --- a/miden/src/cli/run.rs +++ b/miden/src/cli/run.rs @@ -1,6 +1,6 @@ -use super::data::{Debug, InputFile, Libraries, OutputFile, ProgramFile}; +use super::data::{instrument, Debug, InputFile, Libraries, OutputFile, ProgramFile}; use clap::Parser; -use processor::{DefaultHost, ExecutionOptions}; +use processor::{DefaultHost, ExecutionOptions, ExecutionTrace}; use std::{path::PathBuf, time::Instant}; #[derive(Debug, Clone, Parser)] @@ -37,37 +37,19 @@ pub struct RunCmd { impl RunCmd { pub fn execute(&self) -> Result<(), String> { - println!("============================================================"); - println!("Run program"); - println!("============================================================"); + println!("==============================================================================="); + println!("Run program: {}", self.assembly_file.display()); + println!("-------------------------------------------------------------------------------"); - // load libraries from files - let libraries = Libraries::new(&self.library_paths)?; - - // load program from file and compile - let program = - ProgramFile::read(&self.assembly_file)?.compile(&Debug::Off, libraries.libraries)?; - - // load input data from file - let input_data = InputFile::read(&self.input_file, &self.assembly_file)?; - - // get execution options - let execution_options = ExecutionOptions::new(Some(self.max_cycles), self.expected_cycles) - .map_err(|err| format!("{err}"))?; - - // fetch the stack and program inputs from the arguments - let stack_inputs = input_data.parse_stack_inputs()?; - let host = DefaultHost::new(input_data.parse_advice_provider()?); - - let program_hash: [u8; 32] = program.hash().into(); - print!("Executing program with hash {}... ", hex::encode(program_hash)); let now = Instant::now(); - // execute program and generate outputs - let trace = processor::execute(&program, stack_inputs, host, execution_options) - .map_err(|err| format!("Failed to generate execution trace = {:?}", err))?; + let (trace, program_hash) = run_program(&self)?; - println!("done ({} ms)", now.elapsed().as_millis()); + println!( + "Executed the program with hash {} in {} ms", + hex::encode(program_hash), + now.elapsed().as_millis() + ); if let Some(output_path) = &self.output_file { // write outputs to file if one was specified @@ -107,3 +89,35 @@ impl RunCmd { Ok(()) } } + +// HELPER FUNCTIONS +// ================================================================================================ + +#[instrument(name = "Running program", skip_all)] +fn run_program(params: &RunCmd) -> Result<(ExecutionTrace, [u8; 32]), String> { + // load libraries from files + let libraries = Libraries::new(¶ms.library_paths)?; + + // load program from file and compile + let program = + ProgramFile::read(¶ms.assembly_file)?.compile(&Debug::Off, libraries.libraries)?; + + // load input data from file + let input_data = InputFile::read(¶ms.input_file, ¶ms.assembly_file)?; + + // get execution options + let execution_options = ExecutionOptions::new(Some(params.max_cycles), params.expected_cycles) + .map_err(|err| format!("{err}"))?; + + // fetch the stack and program inputs from the arguments + let stack_inputs = input_data.parse_stack_inputs()?; + let host = DefaultHost::new(input_data.parse_advice_provider()?); + + let program_hash: [u8; 32] = program.hash().into(); + + // execute program and generate outputs + let trace = processor::execute(&program, stack_inputs, host, execution_options) + .map_err(|err| format!("Failed to generate execution trace = {:?}", err))?; + + Ok((trace, program_hash)) +} diff --git a/miden/src/cli/verify.rs b/miden/src/cli/verify.rs index 9e81863b26..35b360d13a 100644 --- a/miden/src/cli/verify.rs +++ b/miden/src/cli/verify.rs @@ -22,9 +22,9 @@ pub struct VerifyCmd { impl VerifyCmd { pub fn execute(&self) -> Result<(), String> { - println!("============================================================"); - println!("Verify program"); - println!("============================================================"); + println!("==============================================================================="); + println!("Verifying proof: {}", self.proof_file.display()); + println!("-------------------------------------------------------------------------------"); // read program hash from input let program_hash = ProgramHash::read(&self.program_hash)?; @@ -41,7 +41,6 @@ impl VerifyCmd { // load proof from file let proof = ProofFile::read(&Some(self.proof_file.clone()), &self.proof_file)?; - println!("verifying program..."); let now = Instant::now(); // TODO accept kernel as CLI argument diff --git a/miden/src/examples/mod.rs b/miden/src/examples/mod.rs index efe7c9dd17..1030f047a4 100644 --- a/miden/src/examples/mod.rs +++ b/miden/src/examples/mod.rs @@ -1,7 +1,7 @@ use clap::Parser; use miden::{ExecutionProof, Host, Program, ProgramInfo, ProvingOptions, StackInputs}; use processor::{ExecutionOptions, ExecutionOptionsError, ONE, ZERO}; -use std::io::Write; + use std::time::Instant; pub mod blake3; @@ -79,12 +79,6 @@ impl ExampleOptions { pub fn execute(&self) -> Result<(), String> { println!("============================================================"); - // configure logging - env_logger::Builder::new() - .format(|buf, record| writeln!(buf, "{}", record.args())) - .filter_level(log::LevelFilter::Debug) - .init(); - let proof_options = self.get_proof_options().map_err(|err| format!("{err}"))?; // instantiate and prepare the example diff --git a/miden/src/main.rs b/miden/src/main.rs index cd3e8bb64b..53b5da10e7 100644 --- a/miden/src/main.rs +++ b/miden/src/main.rs @@ -1,6 +1,8 @@ use clap::Parser; use core::fmt; use miden::{AssemblyError, ExecutionError}; +use tracing_forest::ForestLayer; +use tracing_subscriber::{prelude::*, EnvFilter}; mod cli; mod examples; @@ -53,6 +55,17 @@ pub fn main() { // read command-line args let cli = Cli::parse(); + // configure logging + // if logging level is not specified, set level to "warn" + if std::env::var("MIDEN_LOG").is_err() { + std::env::set_var("MIDEN_LOG", "warn"); + } + + tracing_subscriber::registry::Registry::default() + .with(EnvFilter::from_env("MIDEN_LOG")) + .with(ForestLayer::default()) + .init(); + // execute cli action if let Err(error) = cli.execute() { println!("{}", error); diff --git a/processor/Cargo.toml b/processor/Cargo.toml index fbfeae6108..681f2b544a 100644 --- a/processor/Cargo.toml +++ b/processor/Cargo.toml @@ -20,10 +20,10 @@ doctest = false concurrent = ["std", "winter-prover/concurrent"] default = ["std"] internals = [] -std = ["log/std", "vm-core/std", "winter-prover/std"] +std = ["tracing/attributes", "vm-core/std", "winter-prover/std"] [dependencies] -log = { version = "0.4", default-features = false, optional = true } +tracing = { version = "0.1", default-features = false, optional = true } vm-core = { package = "miden-core", path = "../core", version = "0.8", default-features = false } miden-air = { package = "miden-air", path = "../air", version = "0.8", default-features = false } winter-prover = { package = "winter-prover", version = "0.7", default-features = false } diff --git a/processor/src/lib.rs b/processor/src/lib.rs index 78b8d885ed..f080e3c226 100644 --- a/processor/src/lib.rs +++ b/processor/src/lib.rs @@ -116,6 +116,7 @@ pub struct ChipletsTrace { /// Returns an execution trace resulting from executing the provided program against the provided /// inputs. +#[cfg_attr(feature = "std", tracing::instrument("Executing program", skip_all))] pub fn execute( program: &Program, stack_inputs: StackInputs, diff --git a/prover/Cargo.toml b/prover/Cargo.toml index 145aeb2539..dd514b503d 100644 --- a/prover/Cargo.toml +++ b/prover/Cargo.toml @@ -16,12 +16,12 @@ rust-version = "1.73" concurrent = ["processor/concurrent", "std", "winter-prover/concurrent"] default = ["std"] metal = ["dep:ministark-gpu", "dep:elsa", "dep:pollster", "concurrent", "std"] -std = ["air/std", "processor/std", "log/std", "winter-prover/std"] +std = ["air/std", "processor/std", "tracing/attributes", "winter-prover/std"] [dependencies] air = { package = "miden-air", path = "../air", version = "0.8", default-features = false } -log = { version = "0.4", default-features = false, optional = true } processor = { package = "miden-processor", path = "../processor", version = "0.8", default-features = false } +tracing = { version = "0.1", default-features = false, optional = true } winter-prover = { package = "winter-prover", version = "0.7", default-features = false } [target.'cfg(all(target_arch = "aarch64", target_os = "macos"))'.dependencies] diff --git a/prover/src/gpu.rs b/prover/src/gpu.rs index 530d18fa74..af04c4cee3 100644 --- a/prover/src/gpu.rs +++ b/prover/src/gpu.rs @@ -3,9 +3,9 @@ use super::{ crypto::{RandomCoin, Rpo256, RpoDigest}, - debug, + event, math::fft, - ExecutionProver, ExecutionTrace, Felt, FieldElement, ProcessorAir, PublicInputs, + ExecutionProver, ExecutionTrace, Felt, FieldElement, Level, ProcessorAir, PublicInputs, WinterProofOptions, }; use elsa::FrozenVec; @@ -115,7 +115,8 @@ where let offsets = get_evaluation_offsets::(composition_poly.column_len(), blowup, domain.offset()); let segments = build_segments(composition_poly.data(), domain.trace_twiddles(), &offsets); - debug!( + event!( + Level::INFO, "Evaluated {} composition polynomial columns over LDE domain (2^{} elements) in {} ms", composition_poly.num_columns(), offsets.len().ilog2(), @@ -155,7 +156,8 @@ where let leaves = row_hashes.into_iter().map(RpoDigest::new).collect(); let commitment = MerkleTree::::from_raw_parts(nodes, leaves).unwrap(); let constraint_commitment = ConstraintCommitment::new(composed_evaluations, commitment); - debug!( + event!( + Level::INFO, "Computed constraint evaluation commitment on the GPU (Merkle tree of depth {}) in {} ms", constraint_commitment.tree_depth(), now.elapsed().as_millis() @@ -425,7 +427,8 @@ fn build_trace_commitment>( let nodes = block_on(tree_nodes).into_iter().map(RpoDigest::new).collect(); let leaves = row_hashes.into_iter().map(RpoDigest::new).collect(); let trace_tree = MerkleTree::from_raw_parts(nodes, leaves).unwrap(); - debug!( + event!( + Level::INFO, "Extended (on CPU) and committed (on GPU) to an execution trace of {} columns from 2^{} to 2^{} steps in {} ms", trace_polys.num_cols(), trace_polys.num_rows().ilog2(), diff --git a/prover/src/lib.rs b/prover/src/lib.rs index feb4ac63f1..7b748484f9 100644 --- a/prover/src/lib.rs +++ b/prover/src/lib.rs @@ -9,14 +9,14 @@ use processor::{ math::{Felt, FieldElement}, ExecutionTrace, }; +#[cfg(feature = "std")] +use tracing::{event, instrument, Level}; use winter_prover::{ matrix::ColMatrix, AuxTraceRandElements, ConstraintCompositionCoefficients, DefaultConstraintEvaluator, DefaultTraceLde, ProofOptions as WinterProofOptions, Prover, StarkDomain, TraceInfo, TracePolyTable, }; -#[cfg(feature = "std")] -use log::debug; #[cfg(feature = "std")] use std::time::Instant; #[cfg(feature = "std")] @@ -47,6 +47,7 @@ pub use winter_prover::StarkProof; /// /// # Errors /// Returns an error if program execution or STARK proof generation fails for any reason. +#[cfg_attr(feature = "std", instrument("Proving program", skip_all))] pub fn prove( program: &Program, stack_inputs: StackInputs, @@ -67,7 +68,8 @@ where * 100 / trace.trace_len_summary().padded_trace_len(); #[cfg(feature = "std")] - debug!( + event!( + Level::INFO, "Generated execution trace of {} columns and {} steps ({}% padded) in {} ms", trace.layout().main_trace_width(), trace.trace_len_summary().padded_trace_len(), diff --git a/verifier/Cargo.toml b/verifier/Cargo.toml index 94b35e8253..40808dc200 100644 --- a/verifier/Cargo.toml +++ b/verifier/Cargo.toml @@ -18,9 +18,10 @@ doctest = false [features] default = ["std"] -std = ["air/std", "vm-core/std", "winter-verifier/std"] +std = ["air/std", "tracing/attributes", "vm-core/std", "winter-verifier/std"] [dependencies] air = { package = "miden-air", path = "../air", version = "0.8", default-features = false } +tracing = { version = "0.1", default-features = false, optional = true } vm-core = { package = "miden-core", path = "../core", version = "0.8", default-features = false } winter-verifier = { package = "winter-verifier", version = "0.7", default-features = false } diff --git a/verifier/src/lib.rs b/verifier/src/lib.rs index dc7f33f7c0..8669d82752 100644 --- a/verifier/src/lib.rs +++ b/verifier/src/lib.rs @@ -51,6 +51,7 @@ pub use air::ExecutionProof; /// - The provided proof does not prove a correct execution of the program. /// - The the protocol parameters used to generate the proof is not in the set of acceptable /// parameters. +#[cfg_attr(feature = "std", tracing::instrument("Verifying program", skip_all))] pub fn verify( program_info: ProgramInfo, stack_inputs: StackInputs,