Improve logging (#2321)

Cleans up the log a little bit, moving some logs to trace level. Especially related to JIT, which fails quite frequently still. For example, this exposes the issue fixed by #2322: ``` $ RUST_LOG=debug cargo run pil test_data/std/binary_large_test.asm -o output -f --linker-mode bus ... [00:00:00 (ETA: 00:00:00)] ░░░░░░░░░░░░░░░░░░░░ 0% - Starting... Compiling JIT function for Machine: Secondary machine 0: main_binary (BlockMachine) Identity: main::instr_and $ [0, main::X0, main::X1, main::X2] is main_binary::latch * main_binary::sel[0] $ [main_binary::operation_id, main_binary::A, main_binary::B, main_binary::C] Known args: 1110 => Error generating JIT code: Code generation failed: Incomplete machine calls: Constr::PhantomBusInteraction(18446744069414584320 * (main_binary::latch * main_binary::sel[0]), [1, main_binary::operation_id, main_binary::A, main_binary::B, main_binary::C], main_binary::latch); (row -1) Constr::PhantomBusInteraction(18446744069414584320 * (main_binary::latch * main_binary::sel[0]), [1, main_binary::operation_id, main_binary::A, main_binary::B, main_binary::C], main_binary::latch); (row 0) Constr::PhantomBusInteraction(18446744069414584320 * (main_binary::latch * main_binary::sel[0]), [1, main_binary::operation_id, main_binary::A, main_binary::B, main_binary::C], main_binary::latch); (row 1) Constr::PhantomBusInteraction(18446744069414584320 * (main_binary::latch * main_binary::sel[0]), [1, main_binary::operation_id, main_binary::A, main_binary::B, main_binary::C], main_binary::latch); (row 2) ... Compiling JIT function for Machine: Secondary machine 0: main_binary (BlockMachine) Identity: main::instr_or $ [1, main::X0, main::X1, main::X2] is main_binary::latch * main_binary::sel[1] $ [main_binary::operation_id, main_binary::A, main_binary::B, main_binary::C] Known args: 1110 => Error generating JIT code: Code generation failed: Incomplete machine calls: Constr::PhantomBusInteraction(18446744069414584320 * (main_binary::latch * main_binary::sel[0]), [1, main_binary::operation_id, main_binary::A, main_binary::B, main_binary::C], main_binary::latch); (row -1) Constr::PhantomBusInteraction(18446744069414584320 * (main_binary::latch * main_binary::sel[0]), [1, main_binary::operation_id, main_binary::A, main_binary::B, main_binary::C], main_binary::latch); (row 0) Constr::PhantomBusInteraction(18446744069414584320 * (main_binary::latch * main_binary::sel[0]), [1, main_binary::operation_id, main_binary::A, main_binary::B, main_binary::C], main_binary::latch); (row 1) Constr::PhantomBusInteraction(18446744069414584320 * (main_binary::latch * main_binary::sel[0]), [1, main_binary::operation_id, main_binary::A, main_binary::B, main_binary::C], main_binary::latch); (row 2) ... Compiling JIT function for Machine: Secondary machine 0: main_binary (BlockMachine) Identity: main::instr_xor $ [2, main::X0, main::X1, main::X2] is main_binary::latch * main_binary::sel[2] $ [main_binary::operation_id, main_binary::A, main_binary::B, main_binary::C] Known args: 1110 => Error generating JIT code: Code generation failed: Incomplete machine calls: Constr::PhantomBusInteraction(18446744069414584320 * (main_binary::latch * main_binary::sel[0]), [1, main_binary::operation_id, main_binary::A, main_binary::B, main_binary::C], main_binary::latch); (row -1) Constr::PhantomBusInteraction(18446744069414584320 * (main_binary::latch * main_binary::sel[0]), [1, main_binary::operation_id, main_binary::A, main_binary::B, main_binary::C], main_binary::latch); (row 0) Constr::PhantomBusInteraction(18446744069414584320 * (main_binary::latch * main_binary::sel[0]), [1, main_binary::operation_id, main_binary::A, main_binary::B, main_binary::C], main_binary::latch); (row 1) Constr::PhantomBusInteraction(18446744069414584320 * (main_binary::latch * main_binary::sel[0]), [1, main_binary::operation_id, main_binary::A, main_binary::B, main_binary::C], main_binary::latch); (row 2) ... Found loop with period 1 starting at row 100 101 of 128 rows are used in machine 'Main machine (Dynamic)'. Looping failed. Trying to generate regularly again. (Use RUST_LOG=debug to see whether this happens more often.) 128 / 129 [00:00:00 (ETA: 00:00:00)] ████████████████████ 100% - Starting... Finalizing VM: Main machine (Dynamic) Secondary machine 0: main_binary (BlockMachine): 0 / 18 blocks computed via JIT. 72 of 128 rows are used in machine 'Secondary machine 0: main_binary (BlockMachine)'. == Witgen profile (570 events) 45.5% ( 975.3ms): Secondary machine 0: main_binary (BlockMachine) 44.6% ( 956.3ms): FixedLookup 6.1% ( 131.3ms): multiplicity witgen 3.5% ( 75.7ms): witgen (outer code) 0.2% ( 4.2ms): Main machine (Dynamic) --------------------------- ==> Total: 2.142724334s ``` --------- Co-authored-by: chriseth <[email protected]>
powdr-labs · Jan 10, 2025 · 1ee1505 · 1ee1505
1 parent e4d9fcb
commit 1ee1505
Show file tree

Hide file tree

Showing 5 changed files with 36 additions and 16 deletions.
diff --git a/executor/src/witgen/jit/block_machine_processor.rs b/executor/src/witgen/jit/block_machine_processor.rs
@@ -79,15 +79,15 @@ impl<'a, T: FieldElement> BlockMachineProcessor<'a, T> {
         match self.solve_block(can_process, &mut witgen, connection.right) {
             Ok(()) => Ok(witgen.finish()),
             Err(e) => {
-                log::debug!("\nCode generation failed for connection:\n  {connection}");
+                log::trace!("\nCode generation failed for connection:\n  {connection}");
                 let known_args_str = known_args
                     .iter()
                     .enumerate()
                     .filter_map(|(i, b)| b.then_some(connection.right.expressions[i].to_string()))
                     .join("\n  ");
-                log::debug!("Known arguments:\n  {known_args_str}");
-                log::debug!("Error:\n  {e}");
-                log::debug!(
+                log::trace!("Known arguments:\n  {known_args_str}");
+                log::trace!("Error:\n  {e}");
+                log::trace!(
                     "The following code was generated so far:\n{}",
                     format_code(witgen.code())
                 );

diff --git a/executor/src/witgen/jit/function_cache.rs b/executor/src/witgen/jit/function_cache.rs
@@ -1,6 +1,7 @@
 use std::{collections::HashMap, hash::Hash};
 
 use bit_vec::BitVec;
+use itertools::Itertools;
 use powdr_number::{FieldElement, KnownField};
 
 use crate::witgen::{
@@ -29,6 +30,8 @@ pub struct FunctionCache<'a, T: FieldElement> {
     witgen_functions: HashMap<CacheKey, Option<WitgenFunction<T>>>,
     column_layout: ColumnLayout,
     block_size: usize,
+    machine_name: String,
+    parts: MachineParts<'a, T>,
 }
 
 impl<'a, T: FieldElement> FunctionCache<'a, T> {
@@ -38,6 +41,7 @@ impl<'a, T: FieldElement> FunctionCache<'a, T> {
         block_size: usize,
         latch_row: usize,
         metadata: ColumnLayout,
+        machine_name: String,
     ) -> Self {
         let processor =
             BlockMachineProcessor::new(fixed_data, parts.clone(), block_size, latch_row);
@@ -47,6 +51,8 @@ impl<'a, T: FieldElement> FunctionCache<'a, T> {
             column_layout: metadata,
             witgen_functions: HashMap::new(),
             block_size,
+            machine_name,
+            parts,
         }
     }
 
@@ -90,12 +96,24 @@ impl<'a, T: FieldElement> FunctionCache<'a, T> {
         mutable_state: &MutableState<'a, T, Q>,
         cache_key: &CacheKey,
     ) -> Option<WitgenFunction<T>> {
-        log::trace!("Compiling JIT function for {:?}", cache_key);
+        log::debug!(
+            "Compiling JIT function for\n  Machine: {}\n  Connection: {}\n   Inputs: {:?}",
+            self.machine_name,
+            self.parts.connections[&cache_key.identity_id],
+            cache_key.known_args
+        );
 
         self.processor
             .generate_code(mutable_state, cache_key.identity_id, &cache_key.known_args)
+            .map_err(|e| {
+                // These errors can be pretty verbose and are quite common currently.
+                let e = e.to_string().lines().take(5).join("\n");
+                log::debug!("=> Error generating JIT code: {e}\n...");
+                e
+            })
             .ok()
             .map(|code| {
+                log::debug!("=> Success!");
                 let is_in_bounds = code
                     .iter()
                     .flat_map(|effect| effect.referenced_variables())

diff --git a/executor/src/witgen/machines/block_machine.rs b/executor/src/witgen/machines/block_machine.rs
@@ -118,6 +118,14 @@ impl<'a, T: FieldElement> BlockMachine<'a, T> {
             fixed_data,
         );
         let layout = data.layout();
+        let function_cache = FunctionCache::new(
+            fixed_data,
+            parts.clone(),
+            block_size,
+            latch_row,
+            layout,
+            name.clone(),
+        );
         Some(BlockMachine {
             name,
             degree_range,
@@ -134,13 +142,7 @@ impl<'a, T: FieldElement> BlockMachine<'a, T> {
                 latch_row,
                 parts.identities.len(),
             ),
-            function_cache: FunctionCache::new(
-                fixed_data,
-                parts.clone(),
-                block_size,
-                latch_row,
-                layout,
-            ),
+            function_cache,
             block_count_jit: 0,
             block_count_runtime: 0,
         })

diff --git a/executor/src/witgen/mod.rs b/executor/src/witgen/mod.rs
@@ -227,7 +227,7 @@ impl<'a, 'b, T: FieldElement> WitnessGenerator<'a, 'b, T> {
                 let discard = references_later_stage_challenge || references_later_stage_witness;
 
                 if discard {
-                    log::debug!("Skipping identity that references later-stage items: {identity}",);
+                    log::trace!("Skipping identity that references later-stage items: {identity}",);
                 }
                 !discard
             })

diff --git a/executor/src/witgen/processor.rs b/executor/src/witgen/processor.rs
@@ -662,15 +662,15 @@ Known values in current row (local: {row_index}, global {global_row_index}):
             .process_identity(identity, &row_pair)
             .is_err()
         {
-            log::debug!(
+            log::trace!(
                 "Previous {}",
                 self.data[row_index - 1].render_values(true, self.parts)
             );
-            log::debug!(
+            log::trace!(
                 "Proposed {:?}",
                 proposed_row.render_values(true, self.parts)
             );
-            log::debug!("Failed on identity: {}", identity);
+            log::trace!("Failed on identity: {}", identity);
 
             return false;
         }