Merge pull request #492 from saulshanabrook/vec-benchmark

Test extraction of vecs & allow disabling messages for performance

Cargo.toml

@@ -84,3 +84,8 @@ libtest-mimic = "0.6.1"
 
 [profile.release]
 incremental = true
+
+# https://github.com/mstange/samply/?tab=readme-ov-file#turn-on-debug-info-for-full-stacks
+[profile.profiling]
+inherits = "release"
+debug = true

README.md

@@ -73,6 +73,22 @@ We use 50ms as our cutoff currently, any benchmarks shorter than that are ignore
 any benchmarks with have changes > 1% when they haven't been modified. Note that all the ignoring is done manually,
 so if you add another example that's short, an admin on the codspeed project will need to manually ignore it.
 
+## Profiling
+
+One way to profile egglog is to use [samply](https://github.com/mstange/samply/). Here's how you can use it:
+
+```bash
+# install samply
+cargo install --locked samply
+# build a profile build which includes debug symbols
+cargo build --profile profiling
+# run the egglog file and profile
+samply record ./target/profiling/egglog tests/extract-vec-bench.egg
+# [optional] run the egglog file without logging or printing messages, which can help reduce the stdout
+# when you are profiling extracting a large expression
+env RUST_LOG=error samply record ./target/profiling/egglog --dont-print-messages tests/extract-vec-bench.egg
+```
+
 # Documentation
 
 To view documentation, run `cargo doc --open`.

benches/example_benchmarks.rs

@@ -1,8 +1,12 @@
 use codspeed_criterion_compat::{criterion_group, criterion_main, Criterion};
 use egglog::EGraph;
 
-fn run_example(filename: &str, program: &str) {
-    EGraph::default()
+fn run_example(filename: &str, program: &str, no_messages: bool) {
+    let mut egraph = EGraph::default();
+    if no_messages {
+        egraph.disable_messages();
+    }
+    egraph
         .parse_and_run_program(Some(filename.to_owned()), program)
         .unwrap();
 }
@@ -17,7 +21,10 @@ pub fn criterion_benchmark(c: &mut Criterion) {
         let name = path.file_stem().unwrap().to_string_lossy().to_string();
         let filename = path.to_string_lossy().to_string();
         let program = std::fs::read_to_string(&filename).unwrap();
-        c.bench_function(&name, |b| b.iter(|| run_example(&filename, &program)));
+        let no_messages = path_string.contains("no-messages");
+        c.bench_function(&name, |b| {
+            b.iter(|| run_example(&filename, &program, no_messages))
+        });
     }
 }
 

src/actions.rs

@@ -339,9 +339,12 @@ impl EGraph {
                     let variants = values[1].bits as i64;
                     if variants == 0 {
                         let (cost, term) = self.extract(values[0], &mut termdag, sort);
-                        let extracted = termdag.to_string(&term);
-                        log::info!("extracted with cost {cost}: {extracted}");
-                        self.print_msg(extracted);
+                        // dont turn termdag into a string if we have messages disabled for performance reasons
+                        if self.messages_enabled() {
+                            let extracted = termdag.to_string(&term);
+                            log::info!("extracted with cost {cost}: {extracted}");
+                            self.print_msg(extracted);
+                        }
                         self.extract_report = Some(ExtractReport::Best {
                             termdag,
                             cost,
@@ -353,17 +356,20 @@ impl EGraph {
                         }
                         let terms =
                             self.extract_variants(sort, values[0], variants as usize, &mut termdag);
-                        log::info!("extracted variants:");
-                        let mut msg = String::default();
-                        msg += "(\n";
-                        assert!(!terms.is_empty());
-                        for expr in &terms {
-                            let str = termdag.to_string(expr);
-                            log::info!("   {str}");
-                            msg += &format!("   {str}\n");
+                        // Same as above, avoid turning termdag into a string if we have messages disabled for performance
+                        if self.messages_enabled() {
+                            log::info!("extracted variants:");
+                            let mut msg = String::default();
+                            msg += "(\n";
+                            assert!(!terms.is_empty());
+                            for expr in &terms {
+                                let str = termdag.to_string(expr);
+                                log::info!("   {str}");
+                                msg += &format!("   {str}\n");
+                            }
+                            msg += ")";
+                            self.print_msg(msg);
                         }
-                        msg += ")";
-                        self.print_msg(msg);
                         self.extract_report = Some(ExtractReport::Variants { termdag, terms });
                     }
 

src/lib.rs

@@ -443,7 +443,8 @@ pub struct EGraph {
     recent_run_report: Option<RunReport>,
     /// The run report unioned over all runs so far.
     overall_run_report: RunReport,
-    msgs: Vec<String>,
+    /// Messages to be printed to the user. If this is `None`, then we are ignoring messages.
+    msgs: Option<Vec<String>>,
 }
 
 impl Default for EGraph {
@@ -463,7 +464,7 @@ impl Default for EGraph {
             extract_report: None,
             recent_run_report: None,
             overall_run_report: Default::default(),
-            msgs: Default::default(),
+            msgs: Some(vec![]),
             type_info: Default::default(),
         };
         egraph
@@ -495,6 +496,23 @@ impl EGraph {
         self.egraphs.push(self.clone());
     }
 
+    /// Disable saving messages to be printed to the user and remove any saved messages.
+    ///
+    /// When messages are disabled the vec of messages returned by evaluating commands will always be empty.
+    pub fn disable_messages(&mut self) {
+        self.msgs = None;
+    }
+
+    /// Enable saving messages to be printed to the user.
+    pub fn enable_messages(&mut self) {
+        self.msgs = Some(vec![]);
+    }
+
+    /// Whether messages are enabled.
+    pub fn messages_enabled(&self) -> bool {
+        self.msgs.is_some()
+    }
+
     /// Pop the current egraph off the stack, replacing
     /// it with the previously pushed egraph.
     /// It preserves the run report and messages from the popped
@@ -1512,12 +1530,18 @@ impl EGraph {
     }
 
     pub(crate) fn print_msg(&mut self, msg: String) {
-        self.msgs.push(msg);
+        if let Some(ref mut msgs) = self.msgs {
+            msgs.push(msg);
+        }
     }
 
     fn flush_msgs(&mut self) -> Vec<String> {
-        self.msgs.dedup_by(|a, b| a.is_empty() && b.is_empty());
-        std::mem::take(&mut self.msgs)
+        if let Some(ref mut msgs) = self.msgs {
+            msgs.dedup_by(|a, b| a.is_empty() && b.is_empty());
+            std::mem::take(msgs)
+        } else {
+            vec![]
+        }
     }
 }
 

src/main.rs

@@ -37,6 +37,8 @@ struct Args {
     /// Number of times to inline leaves
     #[clap(long, default_value = "0")]
     serialize_n_inline_leaves: usize,
+    #[clap(long)]
+    no_messages: bool,
 }
 
 // test if the current command should be evaluated
@@ -103,6 +105,9 @@ fn main() {
         egraph.fact_directory.clone_from(&args.fact_directory);
         egraph.seminaive = !args.naive;
         egraph.run_mode = args.show;
+        if args.no_messages {
+            egraph.disable_messages();
+        }
         egraph
     };
 

tests/no-messages/README.md

@@ -0,0 +1,2 @@
+These tests are run without saving or printing messages, to more accurately profile the performance when its embedded
+in a larger application and we use other ways to get the output, like the extraction report.