diff --git a/Cargo.lock b/Cargo.lock index c87c1802..3204491d 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -37,6 +37,15 @@ dependencies = [ "memchr", ] +[[package]] +name = "aho-corasick" +version = "0.7.18" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "1e37cfd5e7657ada45f742d6e99ca5788580b5c529dc78faf11ece6dc702656f" +dependencies = [ + "memchr", +] + [[package]] name = "ansi_term" version = "0.11.0" @@ -776,6 +785,19 @@ version = "1.6.1" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "e78d4f1cc4ae33bbfc157ed5d5a5ef3bc29227303d595861deb238fcec4e9457" +[[package]] +name = "env_logger" +version = "0.9.0" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "0b2cf0344971ee6c64c31be0d530793fba457d322dfec2810c453d0ef228f9c3" +dependencies = [ + "atty", + "humantime", + "log", + "regex 1.5.4", + "termcolor", +] + [[package]] name = "environment" version = "0.1.1" @@ -1076,6 +1098,12 @@ version = "0.4.3" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "7f24254aa9a54b5c858eaee2f5bccdb46aaf0e486a595ed5fd8f86ba55232a70" +[[package]] +name = "humantime" +version = "2.1.0" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "9a3a5bfb195931eeb336b2a7b4d761daec841b97f947d34394601737a7bba5e4" + [[package]] name = "idna" version = "0.2.3" @@ -1682,13 +1710,24 @@ version = "0.2.11" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "9329abc99e39129fcceabd24cf5d85b4671ef7c29c50e972bc5afe32438ec384" dependencies = [ - "aho-corasick", + "aho-corasick 0.6.10", "memchr", - "regex-syntax", + "regex-syntax 0.5.6", "thread_local", "utf8-ranges", ] +[[package]] +name = "regex" +version = "1.5.4" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "d07a8629359eb56f1e2fb1652bb04212c072a87ba68546a04065d525673ac461" +dependencies = [ + "aho-corasick 0.7.18", + "memchr", + "regex-syntax 0.6.25", +] + [[package]] name = "regex-automata" version = "0.1.10" @@ -1704,6 +1743,12 @@ dependencies = [ "ucd-util", ] +[[package]] +name = "regex-syntax" +version = "0.6.25" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "f497285884f3fcff424ffc933e56d7cbca511def0c9831a7f9b5f6153e3cc89b" + [[package]] name = "remove_dir_all" version = "0.5.3" @@ -1959,6 +2004,15 @@ dependencies = [ "winapi", ] +[[package]] +name = "termcolor" +version = "1.1.2" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "2dfed899f0eb03f32ee8c6a0aabdb8a7949659e3466561fc0adf54e26d88c5f4" +dependencies = [ + "winapi-util", +] + [[package]] name = "textwrap" version = "0.11.0" @@ -2336,10 +2390,12 @@ dependencies = [ "cfg-if 0.1.10", "clap", "dirs", + "env_logger", "fs_extra", "glob 0.2.11", "lazy_static", - "regex", + "log", + "regex 0.2.11", "serde_json", "tempdir", "zokrates_abi", @@ -2378,6 +2434,7 @@ dependencies = [ "git2", "hex", "lazy_static", + "log", "num", "num-bigint 0.2.6", "pairing_ce", @@ -2385,7 +2442,7 @@ dependencies = [ "rand 0.4.6", "rand 0.7.3", "reduce", - "regex", + "regex 0.2.11", "serde", "serde_json", "sha2 0.9.5", diff --git a/changelogs/unreleased/950-schaeff b/changelogs/unreleased/950-schaeff new file mode 100644 index 00000000..1b3e2e0d --- /dev/null +++ b/changelogs/unreleased/950-schaeff @@ -0,0 +1 @@ +Add compiler logs \ No newline at end of file diff --git a/zokrates_cli/Cargo.toml b/zokrates_cli/Cargo.toml index c23bb95f..5ea92243 100644 --- a/zokrates_cli/Cargo.toml +++ b/zokrates_cli/Cargo.toml @@ -12,6 +12,8 @@ bellman = ["zokrates_core/bellman"] ark = ["zokrates_core/ark"] [dependencies] +log = "0.4" +env_logger = "0.9.0" cfg-if = "0.1" clap = "2.26.2" bincode = "0.8.0" diff --git a/zokrates_cli/src/bin.rs b/zokrates_cli/src/bin.rs index 907c65f4..6ce19365 100644 --- a/zokrates_cli/src/bin.rs +++ b/zokrates_cli/src/bin.rs @@ -20,6 +20,8 @@ fn main() { // set a custom panic hook std::panic::set_hook(Box::new(panic_hook)); + env_logger::init(); + cli().unwrap_or_else(|e| { println!("{}", e); std::process::exit(1); diff --git a/zokrates_cli/src/ops/compile.rs b/zokrates_cli/src/ops/compile.rs index ace894b4..cfe17781 100644 --- a/zokrates_cli/src/ops/compile.rs +++ b/zokrates_cli/src/ops/compile.rs @@ -99,6 +99,8 @@ fn cli_compile(sub_matches: &ArgMatches) -> Result<(), String> { let abi_spec_path = Path::new(sub_matches.value_of("abi-spec").unwrap()); let hr_output_path = bin_output_path.to_path_buf().with_extension("ztf"); + log::debug!("Load entry point file {}", path.display()); + let file = File::open(path.clone()) .map_err(|why| format!("Could not open {}: {}", path.display(), why))?; @@ -131,6 +133,9 @@ fn cli_compile(sub_matches: &ArgMatches) -> Result<(), String> { .isolate_branches(sub_matches.is_present("isolate-branches")); let resolver = FileSystemResolver::with_stdlib_root(stdlib_path); + + log::debug!("Compile"); + let artifacts: CompilationArtifacts = compile(source, path, Some(&resolver), &config) .map_err(|e| { format!( @@ -148,6 +153,7 @@ fn cli_compile(sub_matches: &ArgMatches) -> Result<(), String> { let num_constraints = program_flattened.constraint_count(); // serialize flattened program and write to binary file + log::debug!("Serialize program"); let bin_output_file = File::create(&bin_output_path) .map_err(|why| format!("Could not create {}: {}", bin_output_path.display(), why))?; @@ -156,6 +162,7 @@ fn cli_compile(sub_matches: &ArgMatches) -> Result<(), String> { program_flattened.serialize(&mut writer); // serialize ABI spec and write to JSON file + log::debug!("Serialize ABI"); let abi_spec_file = File::create(&abi_spec_path) .map_err(|why| format!("Could not create {}: {}", abi_spec_path.display(), why))?; @@ -173,6 +180,7 @@ fn cli_compile(sub_matches: &ArgMatches) -> Result<(), String> { if sub_matches.is_present("ztf") { // write human-readable output file + log::debug!("Serialize human readable program"); let hr_output_file = File::create(&hr_output_path) .map_err(|why| format!("Could not create {}: {}", hr_output_path.display(), why))?; diff --git a/zokrates_core/Cargo.toml b/zokrates_core/Cargo.toml index e81f04fb..204da484 100644 --- a/zokrates_core/Cargo.toml +++ b/zokrates_core/Cargo.toml @@ -16,6 +16,7 @@ multicore = ["bellman_ce/multicore"] ark = ["ark-ff", "ark-ec", "ark-bn254", "ark-bls12-377", "ark-bw6-761", "ark-gm17", "ark-serialize", "ark-relations", "ark-marlin", "ark-poly", "ark-poly-commit", "zokrates_field/ark", "sha2"] [dependencies] +log = "0.4" cfg-if = "0.1" num = { version = "0.1.36", default-features = false } num-bigint = { version = "0.2", default-features = false } diff --git a/zokrates_core/src/compile.rs b/zokrates_core/src/compile.rs index 093031ec..81b07f2d 100644 --- a/zokrates_core/src/compile.rs +++ b/zokrates_core/src/compile.rs @@ -192,18 +192,23 @@ pub fn compile>( let (typed_ast, abi) = check_with_arena(source, location, resolver, config, &arena)?; // flatten input program + log::debug!("Flatten"); let program_flattened = Flattener::flatten(typed_ast, config); // analyse (constant propagation after call resolution) + log::debug!("Analyse flat program"); let program_flattened = program_flattened.analyse(); // convert to ir + log::debug!("Convert to IR"); let ir_prog = ir::Prog::from(program_flattened); // optimize + log::debug!("Optimise IR"); let optimized_ir_prog = ir_prog.optimize(); // analyse (check constraints) + log::debug!("Analyse IR"); let optimized_ir_prog = optimized_ir_prog.analyse(); Ok(CompilationArtifacts { @@ -231,7 +236,12 @@ fn check_with_arena<'ast, T: Field, E: Into>( arena: &'ast Arena, ) -> Result<(ZirProgram<'ast, T>, Abi), CompileErrors> { let source = arena.alloc(source); - let compiled = compile_program::(source, location, resolver, &arena)?; + + log::debug!("Parse program with entry file {}", location.display()); + + let compiled = parse_program::(source, location, resolver, &arena)?; + + log::debug!("Check semantics"); // check semantics let typed_ast = Checker::check(compiled) @@ -239,13 +249,15 @@ fn check_with_arena<'ast, T: Field, E: Into>( let main_module = typed_ast.main.clone(); + log::debug!("Run static analysis"); + // analyse (unroll and constant propagation) typed_ast .analyse(config) .map_err(|e| CompileErrors(vec![CompileErrorInner::from(e).in_file(&main_module)])) } -pub fn compile_program<'ast, T: Field, E: Into>( +pub fn parse_program<'ast, T: Field, E: Into>( source: &'ast str, location: FilePath, resolver: Option<&dyn Resolver>, @@ -253,7 +265,7 @@ pub fn compile_program<'ast, T: Field, E: Into>( ) -> Result, CompileErrors> { let mut modules = HashMap::new(); - let main = compile_module::(&source, location.clone(), resolver, &mut modules, &arena)?; + let main = parse_module::(&source, location.clone(), resolver, &mut modules, &arena)?; modules.insert(location.clone(), main); @@ -263,21 +275,29 @@ pub fn compile_program<'ast, T: Field, E: Into>( }) } -pub fn compile_module<'ast, T: Field, E: Into>( +pub fn parse_module<'ast, T: Field, E: Into>( source: &'ast str, location: FilePath, resolver: Option<&dyn Resolver>, modules: &mut HashMap>, arena: &'ast Arena, ) -> Result, CompileErrors> { + log::debug!("Generate pest AST for {}", location.display()); + let ast = pest::generate_ast(&source) .map_err(|e| CompileErrors::from(CompileErrorInner::from(e).in_file(&location)))?; + log::debug!("Process macros for {}", location.display()); + let ast = process_macros::(ast) .map_err(|e| CompileErrors::from(CompileErrorInner::from(e).in_file(&location)))?; + log::debug!("Generate absy for {}", location.display()); + let module_without_imports: Module = Module::from(ast); + log::debug!("Apply imports to absy for {}", location.display()); + Importer::apply_imports::( module_without_imports, location.clone(), diff --git a/zokrates_core/src/flatten/mod.rs b/zokrates_core/src/flatten/mod.rs index efc538d5..126190b8 100644 --- a/zokrates_core/src/flatten/mod.rs +++ b/zokrates_core/src/flatten/mod.rs @@ -40,18 +40,18 @@ pub struct Flattener<'ast, T: Field> { } trait FlattenOutput: Sized { - fn flat(&self) -> FlatExpression; + fn flat(self) -> FlatExpression; } impl FlattenOutput for FlatExpression { - fn flat(&self) -> FlatExpression { - self.clone() + fn flat(self) -> FlatExpression { + self } } impl FlattenOutput for FlatUExpression { - fn flat(&self) -> FlatExpression { - self.clone().get_field_unchecked() + fn flat(self) -> FlatExpression { + self.get_field_unchecked() } } @@ -906,8 +906,8 @@ impl<'ast, T: Field> Flattener<'ast, T> { // Y == X * M // 0 == (1-Y) * X - assert!(lhs.metadata.clone().unwrap().should_reduce.to_bool()); - assert!(rhs.metadata.clone().unwrap().should_reduce.to_bool()); + assert!(lhs.metadata.as_ref().unwrap().should_reduce.to_bool()); + assert!(rhs.metadata.as_ref().unwrap().should_reduce.to_bool()); let lhs = self .flatten_uint_expression(statements_flattened, lhs) @@ -925,7 +925,7 @@ impl<'ast, T: Field> Flattener<'ast, T> { ); let eq = self.flatten_boolean_expression( statements_flattened, - BooleanExpression::FieldEq(box lhs.clone(), box rhs.clone()), + BooleanExpression::FieldEq(box lhs, box rhs), ); FlatExpression::Add(box eq, box lt) } @@ -1019,7 +1019,7 @@ impl<'ast, T: Field> Flattener<'ast, T> { ); let eq = self.flatten_boolean_expression( statements_flattened, - BooleanExpression::UintEq(box lhs.clone(), box rhs.clone()), + BooleanExpression::UintEq(box lhs, box rhs), ); FlatExpression::Add(box eq, box lt) } @@ -1046,7 +1046,7 @@ impl<'ast, T: Field> Flattener<'ast, T> { box x.clone(), box FlatExpression::Sub(box y.clone(), box name_x_or_y.into()), ), - FlatExpression::Mult(box x.clone(), box y.clone()), + FlatExpression::Mult(box x, box y), RuntimeError::Or, )); name_x_or_y.into() @@ -1090,9 +1090,9 @@ impl<'ast, T: Field> Flattener<'ast, T> { bitwidth: UBitwidth, ) -> Vec> { let expression = UExpression::try_from(expression).unwrap(); - let from = expression.metadata.clone().unwrap().bitwidth(); + let from = expression.metadata.as_ref().unwrap().bitwidth(); let p = self.flatten_uint_expression(statements_flattened, expression); - self.get_bits(p, from as usize, bitwidth, statements_flattened) + self.get_bits(&p, from as usize, bitwidth, statements_flattened) .into_iter() .map(FlatUExpression::with_field) .collect() @@ -1129,27 +1129,29 @@ impl<'ast, T: Field> Flattener<'ast, T> { statements_flattened: &mut FlatStatements, embed: FlatEmbed, generics: Vec, - param_expressions: Vec>, + mut param_expressions: Vec>, ) -> Vec> { match embed { crate::embed::FlatEmbed::U64ToBits => self.flatten_u_to_bits( statements_flattened, - param_expressions[0].clone(), + param_expressions.pop().unwrap(), 64.into(), ), crate::embed::FlatEmbed::U32ToBits => self.flatten_u_to_bits( statements_flattened, - param_expressions[0].clone(), + param_expressions.pop().unwrap(), 32.into(), ), crate::embed::FlatEmbed::U16ToBits => self.flatten_u_to_bits( statements_flattened, - param_expressions[0].clone(), + param_expressions.pop().unwrap(), 16.into(), ), - crate::embed::FlatEmbed::U8ToBits => { - self.flatten_u_to_bits(statements_flattened, param_expressions[0].clone(), 8.into()) - } + crate::embed::FlatEmbed::U8ToBits => self.flatten_u_to_bits( + statements_flattened, + param_expressions.pop().unwrap(), + 8.into(), + ), crate::embed::FlatEmbed::U64FromBits => { vec![self.flatten_bits_to_u(statements_flattened, param_expressions, 64.into())] } @@ -1294,10 +1296,7 @@ impl<'ast, T: Field> Flattener<'ast, T> { self.define(e, statements_flattened).into() } else if n == T::from(1) { self.define( - FlatExpression::Sub( - box FlatExpression::Number(T::from(1)), - box e.clone(), - ), + FlatExpression::Sub(box FlatExpression::Number(T::from(1)), box e), statements_flattened, ) .into() @@ -1320,8 +1319,8 @@ impl<'ast, T: Field> Flattener<'ast, T> { box FlatExpression::Sub(box y.clone(), box name.into()), ), FlatExpression::Mult( - box FlatExpression::Add(box x.clone(), box x.clone()), - box y.clone(), + box FlatExpression::Add(box x.clone(), box x), + box y, ), RuntimeError::Xor, ), @@ -1392,7 +1391,7 @@ impl<'ast, T: Field> Flattener<'ast, T> { // q in range let _ = self.get_bits( - FlatUExpression::with_field(FlatExpression::from(q)), + &FlatUExpression::with_field(FlatExpression::from(q)), target_bitwidth.to_usize(), target_bitwidth, statements_flattened, @@ -1400,7 +1399,7 @@ impl<'ast, T: Field> Flattener<'ast, T> { // r in range let _ = self.get_bits( - FlatUExpression::with_field(FlatExpression::from(r)), + &FlatUExpression::with_field(FlatExpression::from(r)), target_bitwidth.to_usize(), target_bitwidth, statements_flattened, @@ -1408,7 +1407,7 @@ impl<'ast, T: Field> Flattener<'ast, T> { // r < d <=> r - d + 2**w < 2**w let _ = self.get_bits( - FlatUExpression::with_field(FlatExpression::Add( + &FlatUExpression::with_field(FlatExpression::Add( box FlatExpression::Sub(box r.into(), box d.clone()), box FlatExpression::Number(T::from(2_u128.pow(target_bitwidth.to_usize() as u32))), )), @@ -1515,7 +1514,7 @@ impl<'ast, T: Field> Flattener<'ast, T> { UExpressionInner::Sub(box left, box right) => { // see uint optimizer for the reasoning here let offset = FlatExpression::Number(T::from(2).pow(std::cmp::max( - right.metadata.clone().unwrap().bitwidth() as usize, + right.metadata.as_ref().unwrap().bitwidth() as usize, target_bitwidth as usize, ))); @@ -1819,10 +1818,7 @@ impl<'ast, T: Field> Flattener<'ast, T> { } } (x, y) => self - .define( - FlatExpression::Mult(box x.clone(), box y.clone()), - statements_flattened, - ) + .define(FlatExpression::Mult(box x, box y), statements_flattened) .into(), }) .collect(); @@ -1884,12 +1880,8 @@ impl<'ast, T: Field> Flattener<'ast, T> { let res = match should_reduce { true => { - let bits = self.get_bits( - res.clone(), - actual_bitwidth, - target_bitwidth, - statements_flattened, - ); + let bits = + self.get_bits(&res, actual_bitwidth, target_bitwidth, statements_flattened); let field = if actual_bitwidth > target_bitwidth.to_usize() { bits.iter().enumerate().fold( @@ -1920,7 +1912,7 @@ impl<'ast, T: Field> Flattener<'ast, T> { fn get_bits( &mut self, - e: FlatUExpression, + e: &FlatUExpression, from: usize, to: UBitwidth, statements_flattened: &mut FlatStatements, @@ -1994,7 +1986,8 @@ impl<'ast, T: Field> Flattener<'ast, T> { assert_eq!(bits.len(), to); - self.bits_cache.insert(e.field.unwrap(), bits.clone()); + self.bits_cache + .insert(e.field.clone().unwrap(), bits.clone()); self.bits_cache.insert(sum, bits.clone()); bits @@ -2598,7 +2591,7 @@ impl<'ast, T: Field> Flattener<'ast, T> { // to constrain unsigned integer inputs to be in range, we get their bit decomposition. // it will be cached self.get_bits( - FlatUExpression::with_field(FlatExpression::Identifier(variable)), + &FlatUExpression::with_field(FlatExpression::Identifier(variable)), bitwidth.to_usize(), bitwidth, statements_flattened, diff --git a/zokrates_core/src/imports.rs b/zokrates_core/src/imports.rs index 4578b89d..ad0e475a 100644 --- a/zokrates_core/src/imports.rs +++ b/zokrates_core/src/imports.rs @@ -5,7 +5,7 @@ //! @date 2018 use crate::absy::*; -use crate::compile::compile_module; +use crate::compile::parse_module; use crate::compile::{CompileErrorInner, CompileErrors}; use crate::embed::FlatEmbed; use crate::parser::Position; @@ -222,7 +222,7 @@ impl Importer { Some(_) => {} None => { let source = arena.alloc(source); - let compiled = compile_module::( + let compiled = parse_module::( source, new_location.clone(), resolver, diff --git a/zokrates_core/src/optimizer/mod.rs b/zokrates_core/src/optimizer/mod.rs index 6fd1088a..3f2c064a 100644 --- a/zokrates_core/src/optimizer/mod.rs +++ b/zokrates_core/src/optimizer/mod.rs @@ -21,12 +21,30 @@ use zokrates_field::Field; impl Prog { pub fn optimize(self) -> Self { // remove redefinitions + log::debug!("Constraints: {}", self.constraint_count()); + log::debug!("Optimizer: Remove redefinitions"); let r = RedefinitionOptimizer::optimize(self); + log::debug!("Done"); + // remove constraints that are always satisfied + log::debug!("Constraints: {}", r.constraint_count()); + log::debug!("Optimizer: Remove tautologies"); let r = TautologyOptimizer::optimize(r); - // // deduplicate directives which take the same input + log::debug!("Done"); + + // deduplicate directives which take the same input + log::debug!("Constraints: {}", r.constraint_count()); + log::debug!("Optimizer: Remove duplicate directive"); let r = DirectiveOptimizer::optimize(r); + log::debug!("Done"); + // remove duplicate constraints - DuplicateOptimizer::optimize(r) + log::debug!("Constraints: {}", r.constraint_count()); + log::debug!("Optimizer: Remove duplicate constraints"); + let r = DuplicateOptimizer::optimize(r); + log::debug!("Done"); + + log::debug!("Constraints: {}", r.constraint_count()); + r } } diff --git a/zokrates_core/src/static_analysis/mod.rs b/zokrates_core/src/static_analysis/mod.rs index e66f1505..82b9d6fe 100644 --- a/zokrates_core/src/static_analysis/mod.rs +++ b/zokrates_core/src/static_analysis/mod.rs @@ -73,29 +73,54 @@ impl fmt::Display for Error { impl<'ast, T: Field> TypedProgram<'ast, T> { pub fn analyse(self, config: &CompileConfig) -> Result<(ZirProgram<'ast, T>, Abi), Error> { // inline user-defined constants + log::debug!("Static analyser: Inline constants"); let r = ConstantInliner::inline(self); + log::trace!("\n{}", r); + // isolate branches let r = if config.isolate_branches { - Isolator::isolate(r) + log::debug!("Static analyser: Isolate branches"); + let r = Isolator::isolate(r); + log::trace!("\n{}", r); + r } else { + log::debug!("Static analyser: Branch isolation skipped"); r }; // reduce the program to a single function + log::debug!("Static analyser: Reduce program"); let r = reduce_program(r).map_err(Error::from)?; + log::trace!("\n{}", r); + // generate abi + log::debug!("Static analyser: Generate abi"); let abi = r.abi(); // propagate + log::debug!("Static analyser: Propagate"); let r = Propagator::propagate(r).map_err(Error::from)?; + log::trace!("\n{}", r); + // remove assignment to variable index + log::debug!("Static analyser: Remove variable index"); let r = VariableWriteRemover::apply(r); + log::trace!("\n{}", r); + // detect non constant shifts + log::debug!("Static analyser: Detect non constant shifts"); let r = ShiftChecker::check(r).map_err(Error::from)?; + log::trace!("\n{}", r); + // convert to zir, removing complex types + log::debug!("Static analyser: Convert to zir"); let zir = Flattener::flatten(r); + log::trace!("\n{}", zir); + // optimize uint expressions + log::debug!("Static analyser: Optimize uints"); let zir = UintOptimizer::optimize(zir); + log::trace!("\n{}", zir); Ok((zir, abi)) } @@ -103,12 +128,14 @@ impl<'ast, T: Field> TypedProgram<'ast, T> { impl Analyse for FlatProg { fn analyse(self) -> Self { + log::debug!("Static analyser: Propagate flat"); self.propagate() } } impl Analyse for Prog { fn analyse(self) -> Self { + log::debug!("Static analyser: Detect unconstrained zir"); UnconstrainedVariableDetector::detect(self) } }