feat: move a few logs to debug (#1796)

crates/core/executor/src/events/utils.rs

@@ -64,7 +64,6 @@ where
 /// It's possible to hide rows with 0 count by setting `hide_zeros` to true.
 pub fn generate_execution_report<'a, K, V>(
     table: impl IntoIterator<Item = (K, &'a V)> + 'a,
-    hide_zeros: bool,
 ) -> impl Iterator<Item = String> + 'a
 where
     K: Ord + Display + 'a,
@@ -73,6 +72,6 @@ where
     let (width, lines) = sorted_table_lines(table);
 
     lines
-        .filter(move |(_, count)| !hide_zeros || **count != 0_u64)
+        .filter(move |(_, count)| **count != 0)
         .map(move |(label, count)| format!("  {}", format_table_line(&width, &label, count)))
 }

crates/core/executor/src/report.rs

@@ -68,12 +68,12 @@ impl Add for ExecutionReport {
 impl Display for ExecutionReport {
     fn fmt(&self, f: &mut Formatter<'_>) -> FmtResult {
         writeln!(f, "opcode counts ({} total instructions):", self.total_instruction_count())?;
-        for line in generate_execution_report(self.opcode_counts.as_ref(), false) {
+        for line in generate_execution_report(self.opcode_counts.as_ref()) {
             writeln!(f, "  {line}")?;
         }
 
         writeln!(f, "syscall counts ({} total syscall instructions):", self.total_syscall_count())?;
-        for line in generate_execution_report(self.syscall_counts.as_ref(), true) {
+        for line in generate_execution_report(self.syscall_counts.as_ref()) {
             writeln!(f, "  {line}")?;
         }
 

crates/core/machine/src/utils/logger.rs

@@ -12,14 +12,14 @@ static INIT: Once = Once::new();
 /// Set the `RUST_LOG` environment variable to be set to `info` or `debug`.
 pub fn setup_logger() {
     INIT.call_once(|| {
-        let default_filter = "off";
         let env_filter = EnvFilter::try_from_default_env()
-            .unwrap_or_else(|_| EnvFilter::new(default_filter))
+            .unwrap_or_else(|_| EnvFilter::new("off"))
             .add_directive("hyper=off".parse().unwrap())
             .add_directive("p3_keccak_air=off".parse().unwrap())
             .add_directive("p3_fri=off".parse().unwrap())
             .add_directive("p3_dft=off".parse().unwrap())
-            .add_directive("p3_challenger=off".parse().unwrap());
+            .add_directive("p3_challenger=off".parse().unwrap())
+            .add_directive("sp1_cuda=off".parse().unwrap());
 
         // if the RUST_LOGGER environment variable is set, use it to determine which logger to
         // configure (tracing_forest or tracing_subscriber)

crates/core/machine/src/utils/prove.rs

@@ -29,7 +29,10 @@ use crate::{
     riscv::cost::CostEstimator,
     utils::{chunk_vec, concurrency::TurnBasedSync},
 };
-use sp1_core_executor::{events::generate_execution_report, ExecutionState};
+use sp1_core_executor::{
+    events::{format_table_line, sorted_table_lines},
+    ExecutionState,
+};
 use sp1_primitives::io::SP1PublicValues;
 
 use sp1_core_executor::{
@@ -244,11 +247,11 @@ where
                                         shape_config,
                                     )
                                 });
-                            log::info!("generated {} records", records.len());
+                            tracing::debug!("generated {} records", records.len());
                             reset_seek(&mut checkpoint);
 
                             // Wait for our turn to update the state.
-                            log::info!("waiting for turn {}", index);
+                            tracing::debug!("waiting for turn {}", index);
                             record_gen_sync.wait_for_turn(index);
 
                             // Update the public values & prover state for the shards which contain
@@ -274,7 +277,7 @@ where
 
                             // See if any deferred shards are ready to be committed to.
                             let mut deferred = deferred.split(done, opts.split_opts);
-                            log::info!("deferred {} records", deferred.len());
+                            tracing::debug!("deferred {} records", deferred.len());
 
                             // Update the public values & prover state for the shards which do not
                             // contain "cpu events" before committing to them.
@@ -297,7 +300,7 @@ where
                             records.append(&mut deferred);
 
                             // Collect the checkpoints to be used again in the phase 2 prover.
-                            log::info!("collecting checkpoints");
+                            tracing::debug!("collecting checkpoints");
                             let mut checkpoints = checkpoints.lock().unwrap();
                             checkpoints.push_back((index, checkpoint, done));
 
@@ -307,7 +310,7 @@ where
                             // Fix the shape of the records.
                             if let Some(shape_config) = shape_config {
                                 for record in records.iter_mut() {
-                                    tracing::info!("fixing shape");
+                                    tracing::debug!("fixing shape");
                                     shape_config.fix_shape(record).unwrap();
                                 }
                             }
@@ -478,7 +481,7 @@ where
                                         shape_config,
                                     )
                                 });
-                            log::info!("generated {} records", records.len());
+                            log::debug!("generated {} records", records.len());
                             *report_aggregate.lock().unwrap() += report;
                             reset_seek(&mut checkpoint);
 
@@ -508,7 +511,7 @@ where
 
                             // See if any deferred shards are ready to be committed to.
                             let mut deferred = deferred.split(done, opts.split_opts);
-                            log::info!("deferred {} records", deferred.len());
+                            log::debug!("deferred {} records", deferred.len());
 
                             // Update the public values & prover state for the shards which do not
                             // contain "cpu events" before committing to them.
@@ -674,13 +677,23 @@ where
         // Print the opcode and syscall count tables like `du`: sorted by count (descending) and
         // with the count in the first column.
         tracing::info!("execution report (opcode counts):");
-        for line in generate_execution_report(report_aggregate.opcode_counts.as_ref(), false) {
-            tracing::info!("  {line}");
+        let (width, lines) = sorted_table_lines(report_aggregate.opcode_counts.as_ref());
+        for (label, count) in lines {
+            if *count > 0 {
+                tracing::info!("  {}", format_table_line(&width, &label, count));
+            } else {
+                tracing::debug!("  {}", format_table_line(&width, &label, count));
+            }
         }
 
         tracing::info!("execution report (syscall counts):");
-        for line in generate_execution_report(report_aggregate.syscall_counts.as_ref(), true) {
-            tracing::info!("  {line}");
+        let (width, lines) = sorted_table_lines(report_aggregate.syscall_counts.as_ref());
+        for (label, count) in lines {
+            if *count > 0 {
+                tracing::info!("  {}", format_table_line(&width, &label, count));
+            } else {
+                tracing::debug!("  {}", format_table_line(&width, &label, count));
+            }
         }
 
         let proof = MachineProof::<SC> { shard_proofs };

crates/prover/src/lib.rs

@@ -206,7 +206,7 @@ impl<C: SP1ProverComponents> SP1Prover<C> {
         let vk_verification =
             env::var("VERIFY_VK").map(|v| v.eq_ignore_ascii_case("true")).unwrap_or(false);
 
-        tracing::info!("vk verification: {}", vk_verification);
+        tracing::debug!("vk verification: {}", vk_verification);
 
         // Read the shapes from the shapes directory and deserialize them into memory.
         let allowed_vk_map: BTreeMap<[BabyBear; DIGEST_SIZE], usize> = if vk_verification {