diff --git a/executor/src/witgen/generator.rs b/executor/src/witgen/generator.rs index 5a5d26ed3..77e99ee87 100644 --- a/executor/src/witgen/generator.rs +++ b/executor/src/witgen/generator.rs @@ -6,6 +6,7 @@ use number::{DegreeType, FieldElement}; use std::collections::{HashMap, HashSet}; use crate::witgen::data_structures::finalizable_data::FinalizableData; +use crate::witgen::machines::profiling::{record_end, record_start}; use crate::witgen::processor::OuterQuery; use crate::witgen::rows::CellValue; use crate::witgen::EvalValue; @@ -32,9 +33,14 @@ pub struct Generator<'a, T: FieldElement> { global_range_constraints: GlobalConstraints, data: FinalizableData<'a, T>, latch: Option>, + name: String, } impl<'a, T: FieldElement> Machine<'a, T> for Generator<'a, T> { + fn name(&self) -> &str { + &self.name + } + fn process_plookup>( &mut self, mutable_state: &mut MutableState<'a, '_, T, Q>, @@ -103,6 +109,7 @@ impl<'a, T: FieldElement> Machine<'a, T> for Generator<'a, T> { impl<'a, T: FieldElement> Generator<'a, T> { pub fn new( + name: String, fixed_data: &'a FixedData<'a, T>, identities: &[&'a Identity>], witnesses: HashSet, @@ -111,6 +118,7 @@ impl<'a, T: FieldElement> Generator<'a, T> { ) -> Self { let data = FinalizableData::new(&witnesses); Self { + name, fixed_data, identities: identities.to_vec(), witnesses, @@ -120,23 +128,13 @@ impl<'a, T: FieldElement> Generator<'a, T> { } } - pub fn name(&self) -> &str { - let first_witness = self.witnesses.iter().next().unwrap(); - let first_witness_name = self.fixed_data.column_name(first_witness); - let namespace = first_witness_name - .rfind('.') - .map(|idx| &first_witness_name[..idx]); - - // For machines compiled using Powdr ASM we'll always have a namespace, but as a last - // resort we'll use the first witness name. - namespace.unwrap_or(first_witness_name) - } - /// Runs the machine without any arguments from the first row. pub fn run<'b, Q: QueryCallback>(&mut self, mutable_state: &mut MutableState<'a, 'b, T, Q>) { + record_start(self.name()); assert!(self.data.is_empty()); let first_row = self.compute_partial_first_row(mutable_state); self.data = self.process(first_row, 0, mutable_state, None).block; + record_end(self.name()); } fn fill_remaining_rows>( diff --git a/executor/src/witgen/identity_processor.rs b/executor/src/witgen/identity_processor.rs index 8343bb42c..9b5deae64 100644 --- a/executor/src/witgen/identity_processor.rs +++ b/executor/src/witgen/identity_processor.rs @@ -156,7 +156,7 @@ impl<'a, 'b, 'c, T: FieldElement, Q: QueryCallback> IdentityProcessor<'a, 'b, // TODO could it be that multiple machines match? // query the fixed lookup "machine" - if let Some(result) = self.mutable_state.fixed_lookup.process_plookup( + if let Some(result) = self.mutable_state.fixed_lookup.process_plookup_timed( self.fixed_data, rows, identity.kind, @@ -174,9 +174,12 @@ impl<'a, 'b, 'c, T: FieldElement, Q: QueryCallback> IdentityProcessor<'a, 'b, query_callback: self.mutable_state.query_callback, }; - if let Some(result) = - current.process_plookup(&mut mutable_state, identity.kind, &left, &identity.right) - { + if let Some(result) = current.process_plookup_timed( + &mut mutable_state, + identity.kind, + &left, + &identity.right, + ) { return result; } } diff --git a/executor/src/witgen/machines/block_machine.rs b/executor/src/witgen/machines/block_machine.rs index d65574ba2..a750a14e6 100644 --- a/executor/src/witgen/machines/block_machine.rs +++ b/executor/src/witgen/machines/block_machine.rs @@ -62,10 +62,12 @@ pub struct BlockMachine<'a, T: FieldElement> { /// to make progress most quickly. processing_sequence_cache: ProcessingSequenceCache, fixed_data: &'a FixedData<'a, T>, + name: String, } impl<'a, T: FieldElement> BlockMachine<'a, T> { pub fn try_new( + name: String, fixed_data: &'a FixedData<'a, T>, connecting_identities: &[&'a Identity>], identities: &[&'a Identity>], @@ -120,6 +122,7 @@ impl<'a, T: FieldElement> BlockMachine<'a, T> { (0..block_size).map(|i| row_factory.fresh_row(i as DegreeType)), ); BlockMachine { + name, block_size, connecting_rhs, identities: identities.to_vec(), @@ -202,6 +205,10 @@ impl<'a, T: FieldElement> Machine<'a, T> for BlockMachine<'a, T> { }) } + fn name(&self) -> &str { + &self.name + } + fn take_witness_col_values<'b, Q: QueryCallback>( &mut self, _fixed_lookup: &'b mut FixedLookup, @@ -289,18 +296,6 @@ impl<'a, T: FieldElement> BlockMachine<'a, T> { self.data.len() as DegreeType } - fn name(&self) -> &str { - let first_witness = self.witness_cols.iter().next().unwrap(); - let first_witness_name = self.fixed_data.column_name(first_witness); - let namespace = first_witness_name - .rfind('.') - .map(|idx| &first_witness_name[..idx]); - - // For machines compiled using Powdr ASM we'll always have a namespace, but as a last - // resort we'll use the first witness name. - namespace.unwrap_or(first_witness_name) - } - fn process_plookup_internal<'b, Q: QueryCallback>( &mut self, mutable_state: &mut MutableState<'a, 'b, T, Q>, diff --git a/executor/src/witgen/machines/double_sorted_witness_machine.rs b/executor/src/witgen/machines/double_sorted_witness_machine.rs index d9ffb8efd..2c73a2c1c 100644 --- a/executor/src/witgen/machines/double_sorted_witness_machine.rs +++ b/executor/src/witgen/machines/double_sorted_witness_machine.rs @@ -29,6 +29,7 @@ pub struct DoubleSortedWitnesses { trace: BTreeMap<(T, T), Operation>, data: BTreeMap, namespace: String, + name: String, } struct Operation { @@ -42,6 +43,7 @@ impl DoubleSortedWitnesses { } pub fn try_new( + name: String, fixed_data: &FixedData, _identities: &[&Identity>], witness_cols: &HashSet, @@ -82,7 +84,7 @@ impl DoubleSortedWitnesses { .is_none() { Some(Self { - // store the namespace + name, namespace, degree: fixed_data.degree, ..Default::default() @@ -94,6 +96,10 @@ impl DoubleSortedWitnesses { } impl<'a, T: FieldElement> Machine<'a, T> for DoubleSortedWitnesses { + fn name(&self) -> &str { + &self.name + } + fn process_plookup>( &mut self, _mutable_state: &mut MutableState<'a, '_, T, Q>, diff --git a/executor/src/witgen/machines/fixed_lookup_machine.rs b/executor/src/witgen/machines/fixed_lookup_machine.rs index c641cb54d..fa6e79bfa 100644 --- a/executor/src/witgen/machines/fixed_lookup_machine.rs +++ b/executor/src/witgen/machines/fixed_lookup_machine.rs @@ -11,12 +11,15 @@ use number::FieldElement; use crate::witgen::affine_expression::AffineExpression; use crate::witgen::global_constraints::{GlobalConstraints, RangeConstraintSet}; +use crate::witgen::machines::record_start; use crate::witgen::range_constraints::RangeConstraint; use crate::witgen::rows::RowPair; use crate::witgen::util::try_to_simple_poly_ref; use crate::witgen::{EvalError, EvalValue, IncompleteCause}; use crate::witgen::{EvalResult, FixedData}; +use super::record_end; + type Application = (Vec, Vec); type Index = BTreeMap, IndexValue>; @@ -173,6 +176,20 @@ impl FixedLookup { } } + pub fn process_plookup_timed<'b>( + &mut self, + fixed_data: &FixedData, + rows: &RowPair<'_, '_, T>, + kind: IdentityKind, + left: &[AffineExpression<&'b AlgebraicReference, T>], + right: &'b SelectedExpressions>, + ) -> Option> { + record_start("FixedLookup"); + let result = self.process_plookup(fixed_data, rows, kind, left, right); + record_end("FixedLookup"); + result + } + pub fn process_plookup<'b>( &mut self, fixed_data: &FixedData, diff --git a/executor/src/witgen/machines/machine_extractor.rs b/executor/src/witgen/machines/machine_extractor.rs index dd2c20d86..c21ee51e9 100644 --- a/executor/src/witgen/machines/machine_extractor.rs +++ b/executor/src/witgen/machines/machine_extractor.rs @@ -37,6 +37,7 @@ pub fn split_out_machines<'a, T: FieldElement>( let all_witnesses = fixed.witness_cols.keys().collect::>(); let mut remaining_witnesses = all_witnesses.clone(); let mut base_identities = identities.clone(); + let mut id_counter = 0; for id in &identities { // Extract all witness columns in the RHS of the lookup. let lookup_witnesses = &refs_in_selected_expressions(&id.right) & (&remaining_witnesses); @@ -98,22 +99,45 @@ pub fn split_out_machines<'a, T: FieldElement>( .join("\n"), ); - if let Some(machine) = - SortedWitnesses::try_new(fixed, &machine_identities, &machine_witnesses) - { + let first_witness = machine_witnesses.iter().next().unwrap(); + let first_witness_name = fixed.column_name(first_witness); + let namespace = first_witness_name + .rfind('.') + .map(|idx| &first_witness_name[..idx]); + + // For machines compiled using Powdr ASM we'll always have a namespace, but as a last + // resort we'll use the first witness name. + let name = namespace.unwrap_or(first_witness_name); + let id = id_counter; + id_counter += 1; + let name_with_type = |t: &str| format!("Secondary machine {id}: {name} ({t})"); + + if let Some(machine) = SortedWitnesses::try_new( + name_with_type("SortedWitness"), + fixed, + &machine_identities, + &machine_witnesses, + ) { log::info!("Detected machine: sorted witnesses / write-once memory"); machines.push(KnownMachine::SortedWitnesses(machine)); - } else if let Some(machine) = - DoubleSortedWitnesses::try_new(fixed, &machine_identities, &machine_witnesses) - { + } else if let Some(machine) = DoubleSortedWitnesses::try_new( + name_with_type("DoubleSortedWitnesses"), + fixed, + &machine_identities, + &machine_witnesses, + ) { log::info!("Detected machine: memory"); machines.push(KnownMachine::DoubleSortedWitnesses(machine)); - } else if let Some(machine) = - WriteOnceMemory::try_new(fixed, &connecting_identities, &machine_identities) - { + } else if let Some(machine) = WriteOnceMemory::try_new( + name_with_type("WriteOnceMemory"), + fixed, + &connecting_identities, + &machine_identities, + ) { log::info!("Detected machine: write-once memory"); machines.push(KnownMachine::WriteOnceMemory(machine)); } else if let Some(machine) = BlockMachine::try_new( + name_with_type("BlockMachine"), fixed, &connecting_identities, &machine_identities, @@ -144,6 +168,7 @@ pub fn split_out_machines<'a, T: FieldElement>( }) .unwrap(); machines.push(KnownMachine::Vm(Generator::new( + name_with_type("Vm"), fixed, &machine_identities, machine_witnesses, diff --git a/executor/src/witgen/machines/mod.rs b/executor/src/witgen/machines/mod.rs index 768a1b5ba..678b352c0 100644 --- a/executor/src/witgen/machines/mod.rs +++ b/executor/src/witgen/machines/mod.rs @@ -8,6 +8,8 @@ use number::FieldElement; use self::block_machine::BlockMachine; use self::double_sorted_witness_machine::DoubleSortedWitnesses; pub use self::fixed_lookup_machine::FixedLookup; +use self::profiling::record_end; +use self::profiling::record_start; use self::sorted_witness_machine::SortedWitnesses; use self::write_once_memory::WriteOnceMemory; use ast::analyzed::IdentityKind; @@ -23,12 +25,30 @@ mod block_machine; mod double_sorted_witness_machine; mod fixed_lookup_machine; pub mod machine_extractor; +pub mod profiling; mod sorted_witness_machine; mod write_once_memory; /// A machine is a set of witness columns and identities where the columns /// are used on the right-hand-side of lookups. It can process plookups. pub trait Machine<'a, T: FieldElement>: Send + Sync { + /// Like `process_plookup`, but also records the time spent in this machine. + fn process_plookup_timed<'b, Q: QueryCallback>( + &mut self, + mutable_state: &'b mut MutableState<'a, 'b, T, Q>, + kind: IdentityKind, + left: &[AffineExpression<&'a AlgebraicReference, T>], + right: &'a SelectedExpressions>, + ) -> Option> { + record_start(self.name()); + let result = self.process_plookup(mutable_state, kind, left, right); + record_end(self.name()); + result + } + + /// Returns a unique name for this machine. + fn name(&self) -> &str; + /// Process a plookup. Not all values on the LHS need to be available. /// Can update internal data. /// Only return an error if this machine is able to handle the query and @@ -80,6 +100,16 @@ impl<'a, T: FieldElement> Machine<'a, T> for KnownMachine<'a, T> { } } + fn name(&self) -> &str { + match self { + KnownMachine::SortedWitnesses(m) => m.name(), + KnownMachine::DoubleSortedWitnesses(m) => m.name(), + KnownMachine::WriteOnceMemory(m) => m.name(), + KnownMachine::BlockMachine(m) => m.name(), + KnownMachine::Vm(m) => m.name(), + } + } + fn take_witness_col_values<'b, Q: QueryCallback>( &mut self, fixed_lookup: &'b mut FixedLookup, diff --git a/executor/src/witgen/machines/profiling.rs b/executor/src/witgen/machines/profiling.rs new file mode 100644 index 000000000..79b9ec379 --- /dev/null +++ b/executor/src/witgen/machines/profiling.rs @@ -0,0 +1,129 @@ +use std::{ + cell::RefCell, + collections::BTreeMap, + time::{Duration, SystemTime}, +}; + +#[derive(PartialEq, Debug, Copy, Clone)] +enum Event { + Start, + End, +} + +thread_local! { + /// The event log is a list of (event, , time) tuples. + static EVENT_LOG: RefCell> = RefCell::new(Vec::new()); + /// Maps a machine name (assumed to be globally unique) to an ID. + /// This is done so that we can use a usize in the event log. + static NAME_TO_ID: RefCell> = RefCell::new(BTreeMap::new()); +} + +/// Returns the ID for a given machine name, creating a new one if necessary. +fn id_from_name(name: &str) -> usize { + NAME_TO_ID.with(|name_to_id| { + let mut name_to_id = name_to_id.borrow_mut(); + name_to_id.get(name).copied().unwrap_or_else(|| { + let id = name_to_id.len(); + name_to_id.insert(name.to_string(), id); + id + }) + }) +} + +/// Adds the start of a computation to the event log. +pub fn record_start(name: &str) { + let id = id_from_name(name); + EVENT_LOG.with(|s| s.borrow_mut().push((Event::Start, id, SystemTime::now()))); +} + +/// Adds the end of a computation to the event log. +pub fn record_end(name: &str) { + let id = id_from_name(name); + EVENT_LOG.with(|s| s.borrow_mut().push((Event::End, id, SystemTime::now()))); +} + +pub fn reset_and_print_profile_summary() { + EVENT_LOG.with(|event_log| { + let id_to_name = NAME_TO_ID.with(|name_to_id| { + let name_to_id = name_to_id.borrow(); + name_to_id + .iter() + .map(|(name, id)| (*id, name.clone())) + .collect::>() + }); + + // Taking the events out is actually important, because there might be + // multiple (consecutive) runs of witgen in the same thread. + let event_log = std::mem::take(&mut (*event_log.borrow_mut())); + log::info!("\n == Witgen profile ({} events)", event_log.len()); + + // Aggregate time spent in each machine. + let mut time_by_machine = BTreeMap::new(); + assert_eq!(event_log[0].0, Event::Start); + let mut current_time = event_log[0].2; + let mut call_stack = vec![event_log[0].1]; + + for (i, &(event, id, time)) in event_log.iter().enumerate().skip(1) { + // We expect one top-level call, so we should never have an empty call stack. + let current_machine_id = *call_stack.last().unwrap_or_else(|| { + panic!( + "Call stack is empty at index {} (event: {:?}, name: {}, time: {:?})", + i, event, id, time + ) + }); + + // Finish the execution of the currently running machine. + let duration = time.duration_since(current_time).unwrap(); + *time_by_machine + .entry(current_machine_id) + .or_insert(Duration::default()) += duration; + current_time = time; + + // Update the call stack. + match event { + Event::Start => { + assert!(current_machine_id != id, "Unexpected recursive call!"); + call_stack.push(id); + } + Event::End => { + assert_eq!(current_machine_id, id, "Unexpected end of call!"); + call_stack.pop().unwrap(); + } + } + } + + assert!( + call_stack.is_empty(), + "Call stack is not empty: {:?}", + call_stack + ); + + // Sort by time, descending. + let mut time_by_machine = time_by_machine.into_iter().collect::>(); + time_by_machine.sort_by(|a, b| b.1.cmp(&a.1)); + + let total_time = time_by_machine.iter().map(|(_, d)| *d).sum::(); + assert_eq!( + event_log + .last() + .unwrap() + .2 + .duration_since(event_log[0].2) + .unwrap(), + total_time + ); + + for (id, duration) in time_by_machine { + let percentage = (duration.as_secs_f64() / total_time.as_secs_f64()) * 100.0; + log::info!( + " {:>5.1}% ({:>8.1?}): {}", + percentage, + duration, + id_to_name[&id] + ); + } + log::info!(" ---------------------------"); + log::info!(" ==> Total: {:?}", total_time); + log::info!("\n"); + }); +} diff --git a/executor/src/witgen/machines/sorted_witness_machine.rs b/executor/src/witgen/machines/sorted_witness_machine.rs index 40b41af53..2fc1176fa 100644 --- a/executor/src/witgen/machines/sorted_witness_machine.rs +++ b/executor/src/witgen/machines/sorted_witness_machine.rs @@ -29,10 +29,12 @@ pub struct SortedWitnesses<'a, T> { witness_positions: HashMap, data: BTreeMap>>, fixed_data: &'a FixedData<'a, T>, + name: String, } impl<'a, T: FieldElement> SortedWitnesses<'a, T> { pub fn try_new( + name: String, fixed_data: &'a FixedData, identities: &[&Identity>], witnesses: &HashSet, @@ -50,6 +52,7 @@ impl<'a, T: FieldElement> SortedWitnesses<'a, T> { .collect(); SortedWitnesses { + name, key_col, witness_positions, data: Default::default(), @@ -123,6 +126,10 @@ fn check_constraint(constraint: &Expression) -> Option Machine<'a, T> for SortedWitnesses<'a, T> { + fn name(&self) -> &str { + &self.name + } + fn process_plookup>( &mut self, _mutable_state: &mut MutableState<'a, '_, T, Q>, diff --git a/executor/src/witgen/machines/write_once_memory.rs b/executor/src/witgen/machines/write_once_memory.rs index 9f19b2b4d..3826be9c9 100644 --- a/executor/src/witgen/machines/write_once_memory.rs +++ b/executor/src/witgen/machines/write_once_memory.rs @@ -41,10 +41,12 @@ pub struct WriteOnceMemory<'a, T: FieldElement> { key_to_index: BTreeMap, DegreeType>, /// The memory content data: BTreeMap>>, + name: String, } impl<'a, T: FieldElement> WriteOnceMemory<'a, T> { pub fn try_new( + name: String, fixed_data: &'a FixedData<'a, T>, connecting_identities: &[&'a Identity>], identities: &[&Identity>], @@ -103,6 +105,7 @@ impl<'a, T: FieldElement> WriteOnceMemory<'a, T> { } Some(Self { + name, fixed_data, rhs, value_polys, @@ -197,6 +200,10 @@ impl<'a, T: FieldElement> WriteOnceMemory<'a, T> { } impl<'a, T: FieldElement> Machine<'a, T> for WriteOnceMemory<'a, T> { + fn name(&self) -> &str { + &self.name + } + fn process_plookup<'b, Q: QueryCallback>( &mut self, _mutable_state: &'b mut MutableState<'a, 'b, T, Q>, diff --git a/executor/src/witgen/mod.rs b/executor/src/witgen/mod.rs index 29a404247..20ba00559 100644 --- a/executor/src/witgen/mod.rs +++ b/executor/src/witgen/mod.rs @@ -14,6 +14,7 @@ use self::generator::Generator; use self::identity_processor::Machines; use self::machines::machine_extractor::ExtractionOutput; +use self::machines::profiling::{record_end, record_start, reset_and_print_profile_summary}; use self::machines::{FixedLookup, Machine}; mod affine_expression; @@ -36,6 +37,8 @@ mod symbolic_witness_evaluator; mod util; mod vm_processor; +static OUTER_CODE_NAME: &str = "witgen (outer code)"; + pub trait QueryCallback: FnMut(&str) -> Result, String> + Send + Sync {} impl QueryCallback for F where F: FnMut(&str) -> Result, String> + Send + Sync {} @@ -92,6 +95,7 @@ impl<'a, 'b, T: FieldElement, Q: QueryCallback> WitnessGenerator<'a, 'b, T, Q /// Generates the committed polynomial values /// @returns the values (in source order) and the degree of the polynomials. pub fn generate(self) -> Vec<(String, Vec)> { + record_start(OUTER_CODE_NAME); let fixed = FixedData::new( self.analyzed, self.fixed_col_values, @@ -124,6 +128,7 @@ impl<'a, 'b, T: FieldElement, Q: QueryCallback> WitnessGenerator<'a, 'b, T, Q query_callback: &mut query_callback, }; let mut generator = Generator::new( + "Main Machine".to_string(), &fixed, &base_identities, base_witnesses, @@ -149,6 +154,9 @@ impl<'a, 'b, T: FieldElement, Q: QueryCallback> WitnessGenerator<'a, 'b, T, Q .chain(main_columns) .collect::>(); + record_end(OUTER_CODE_NAME); + reset_and_print_profile_summary(); + // Order columns according to the order of declaration. self.analyzed .committed_polys_in_source_order()