From dbcd0bd55846f7cba25f5fe4e5bb8d908b3fba21 Mon Sep 17 00:00:00 2001 From: schaeff Date: Thu, 29 Jul 2021 11:13:54 +0200 Subject: [PATCH] add log to core and env_log to cli --- zokrates_cli/Cargo.toml | 2 + zokrates_cli/src/bin.rs | 2 + zokrates_cli/src/ops/compile.rs | 8 +++ zokrates_core/Cargo.toml | 1 + zokrates_core/src/compile.rs | 28 +++++++-- zokrates_core/src/flatten/mod.rs | 77 +++++++++++------------- zokrates_core/src/imports.rs | 4 +- zokrates_core/src/optimizer/mod.rs | 22 ++++++- zokrates_core/src/static_analysis/mod.rs | 29 ++++++++- 9 files changed, 122 insertions(+), 51 deletions(-) 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 dd05f3f3..f04aedcc 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() } } @@ -905,8 +905,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) @@ -924,7 +924,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) } @@ -1018,7 +1018,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) } @@ -1045,7 +1045,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() @@ -1089,9 +1089,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() @@ -1128,27 +1128,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())] } @@ -1293,10 +1295,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() @@ -1319,8 +1318,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, ), @@ -1391,7 +1390,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, @@ -1399,7 +1398,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, @@ -1407,7 +1406,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))), )), @@ -1514,7 +1513,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, ))); @@ -1818,10 +1817,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(); @@ -1883,12 +1879,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( @@ -1919,7 +1911,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, @@ -1993,7 +1985,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 @@ -2597,7 +2590,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) } }