better compile times working

Cargo.toml

@@ -36,6 +36,7 @@ ordered-float = "3.7.0"
 serde_json = "1.0.103"
 dot-structures = "0.1.1"
 graphviz-rust = "0.8.0"
+serde = "1.0.217"
 
 dag_in_context = { path = "dag_in_context" }
 

infra/profile.py

@@ -91,33 +91,47 @@ def optimize(benchmark):
   print(f'[{benchmark.index}/{benchmark.total}] Optimizing {benchmark.name} with {benchmark.treatment}')
   profile_dir = benchmark_profile_dir(benchmark.name)
   optimized_bril_file = f'{profile_dir}/{benchmark.name}-{benchmark.treatment}.bril'
+  eggcc_run_data = f'{profile_dir}/{benchmark.treatment}-eggcc-run-data.json'
+  llvm_run_data = f'{profile_dir}/{benchmark.treatment}-llvm-run-data.json'
 
   # get the commands we need to run
   (eggcc_run_mode, llvm_args) = get_eggcc_options(benchmark)
   # make the llvm output directory
   os.makedirs(f"{DATA_DIR}/llvm/{benchmark.name}/{benchmark.treatment}", exist_ok=True)
   llvm_out_file = f"{DATA_DIR}/llvm/{benchmark.name}/{benchmark.treatment}/optimized.ll"
 
-  cmd1 = f'{EGGCC_BINARY} {benchmark.path} --run-mode {eggcc_run_mode}'
-  cmd2 = f'{EGGCC_BINARY} {optimized_bril_file} --add-timing {llvm_args} -o {profile_dir}/{benchmark.treatment} --llvm-output-dir {llvm_out_file}'
+  cmd1 = f'{EGGCC_BINARY} {benchmark.path} --run-mode {eggcc_run_mode} --run-data-out {eggcc_run_data}'
+  cmd2 = f'{EGGCC_BINARY} {optimized_bril_file} --run-data-out {llvm_run_data} --add-timing {llvm_args} -o {profile_dir}/{benchmark.treatment} --llvm-output-dir {llvm_out_file}'
 
   print(f'Running c1: {cmd1}', flush=True)
-  start_eggcc = time.time()
   process = subprocess.run(cmd1, shell=True, capture_output=True, text=True)
   process.check_returncode()
-  end_eggcc = time.time()
 
   # write the std out to the optimized bril file
   with open(optimized_bril_file, 'w') as f:
     f.write(process.stdout)
 
   print(f'Running c2: {cmd2}', flush=True)
-  start_llvm = time.time()
   process2 = subprocess.run(cmd2, shell=True)
   process2.check_returncode()
-  end_llvm = time.time()
 
-  res = {"path": f"{profile_dir}/{benchmark.treatment}", "eggccCompileTimeSecs": end_eggcc-start_eggcc, "llvmCompileTimeSecs": end_llvm-start_llvm}
+  eggcc_compile_time = 0
+  # parse json from eggcc run data
+  with open(eggcc_run_data) as f:
+    eggcc_data = json.load(f)
+    secs = eggcc_data["eggcc_compile_time"]["secs"]
+    nanos = eggcc_data["eggcc_compile_time"]["nanos"]
+    eggcc_compile_time = secs + nanos / 1e9
+
+  llvm_compile_time = 0
+  with open(llvm_run_data) as f:
+    llvm_data = json.load(f)
+    secs = llvm_data["llvm_compile_time"]["secs"]
+    nanos = llvm_data["llvm_compile_time"]["nanos"]
+    llvm_compile_time = secs + nanos / 1e9
+
+
+  res = {"path": f"{profile_dir}/{benchmark.treatment}", "eggccCompileTimeSecs": eggcc_compile_time, "llvmCompileTimeSecs": llvm_compile_time}
   return res
 
 

src/main.rs

@@ -33,6 +33,9 @@ struct Args {
     /// Where to put the executable (only for the brillift and llvm modes)
     #[clap(short)]
     output_path: Option<String>,
+    /// Output metadata about the run to a file
+    #[clap(long)]
+    run_data_out: Option<PathBuf>,
     /// Where to put the optimized llvm file (for the llvm mode)
     #[clap(long)]
     llvm_output_dir: Option<PathBuf>,
@@ -77,6 +80,8 @@ fn main() {
     // enable logging
     env_logger::init();
 
+    let start_time = std::time::Instant::now();
+
     if let Some(debug_dir) = args.debug_dir {
         if let Result::Err(error) = visualize(TestProgram::BrilFile(args.file.clone()), debug_dir) {
             eprintln!("{}", error);
@@ -122,13 +127,21 @@ fn main() {
         },
     };
 
-    let result = match run.run() {
+    let mut result = match run.run() {
         Ok(result) => result,
         Err(error) => {
             panic!("{}", error);
         }
     };
 
+    let eggcc_duration = start_time.elapsed();
+    result.eggcc_compile_time = eggcc_duration;
+
+    if let Some(run_data_output_path) = args.run_data_out {
+        let file = std::fs::File::create(run_data_output_path).unwrap();
+        serde_json::to_writer_pretty(file, &result).unwrap();
+    }
+
     if args.interp {
         // just print out the result of interpreting the program
         println!("{}", result.result_interpreted.unwrap());

src/util.rs

@@ -8,10 +8,12 @@ use dag_in_context::schedule::{self};
 use dag_in_context::{build_program, check_roundtrip_egraph, EggccConfig, Schedule};
 
 use dag_in_context::schema::TreeProgram;
+use serde::{Deserialize, Serialize};
 use std::fmt::Debug;
 use std::fs::File;
 use std::io::{Read, Write};
 use std::process::{Command, Stdio};
+use std::time::{Duration, Instant};
 use std::{
     ffi::OsStr,
     fmt::{Display, Formatter},
@@ -430,20 +432,27 @@ pub enum Interpretable {
 /// and a file extension.
 /// For CFGs, the name is the name of the function and the vizalization
 /// is a SVG.
-#[derive(Clone, Debug)]
+#[derive(Clone, Debug, Serialize, Deserialize)]
 pub struct Visualization {
     pub result: String,
     pub file_extension: String,
     pub name: String,
 }
 
-#[derive(Clone)]
-pub struct RunOutput {
+#[derive(Clone, Serialize, Deserialize)]
+pub struct RunResult {
+    #[serde(skip)]
     pub visualizations: Vec<Visualization>,
     // if the result was interpreted, the stdout of interpreting it
     pub result_interpreted: Option<String>,
     pub original_interpreted: Option<String>,
     pub cycles_taken: Option<u64>,
+    // measures the time to optimize the program, without considering lowering
+    // computed in run_bril_llvm
+    pub llvm_compile_time: Duration,
+    // eggcc_compile_time is filled out by main.rs
+    // so that we don't miss any time spent in the main function
+    pub eggcc_compile_time: Duration,
 }
 
 impl Run {
@@ -588,7 +597,7 @@ impl Run {
         name
     }
 
-    pub fn run(&self) -> Result<RunOutput, EggCCError> {
+    pub fn run(&self) -> Result<RunResult, EggCCError> {
         let original_interpreted = if self.interp == InterpMode::Interp {
             Some(Optimizer::interp_bril(
                 &self.prog_with_args.program,
@@ -615,6 +624,7 @@ impl Run {
             None
         };
 
+        let mut llvm_compile_time = Duration::from_millis(0);
         let (visualizations, interpretable_out) = match self.test_type {
             RunMode::Parse => (
                 vec![self.prog_with_args.to_viz()],
@@ -666,8 +676,9 @@ impl Run {
                 let rvsdg = Optimizer::program_to_rvsdg(&self.prog_with_args.program)?;
                 let cfg = rvsdg.to_cfg();
                 let bril = cfg.to_bril();
-                let interpretable =
+                let (interpretable, llvm_time) =
                     self.run_bril_llvm(bril, false, LLVMOptLevel::O0_O0, self.add_timing)?;
+                llvm_compile_time = llvm_time;
                 (vec![], Some(interpretable))
             }
             RunMode::DagToRvsdg => {
@@ -889,12 +900,13 @@ impl Run {
                 let optimize_brillvm = self.optimize_bril_llvm.expect(
                     "optimize_bril_llvm is a required flag when running RunMode::CompileBrilLLVM",
                 );
-                let interpretable = self.run_bril_llvm(
+                let (interpretable, llvm_time) = self.run_bril_llvm(
                     self.prog_with_args.program.clone(),
                     optimize_egglog,
                     optimize_brillvm,
                     self.add_timing,
                 )?;
+                llvm_compile_time = llvm_time;
                 (vec![], Some(interpretable))
             }
             RunMode::TestBenchmark => {
@@ -919,7 +931,7 @@ impl Run {
                     };
 
                     for optimize_llvm in [LLVMOptLevel::O0_O0, LLVMOptLevel::O3_O0] {
-                        let interpretable = self.run_bril_llvm(
+                        let (interpretable, _time) = self.run_bril_llvm(
                             resulting_bril.clone(),
                             false,
                             optimize_llvm,
@@ -968,11 +980,14 @@ impl Run {
         };
         let cycles_taken = result_interpreted.as_ref().map(|val| val.1).unwrap_or(None);
 
-        Ok(RunOutput {
+        Ok(RunResult {
             visualizations,
             result_interpreted: result_interpreted.map(|val| val.0),
             original_interpreted,
             cycles_taken,
+            llvm_compile_time,
+            // eggcc_compile_time is filled out by main.rs
+            eggcc_compile_time: Duration::from_millis(0),
         })
     }
 
@@ -1049,7 +1064,7 @@ impl Run {
         optimize_egglog: bool,
         llvm_level: LLVMOptLevel,
         add_timing: bool,
-    ) -> Result<Interpretable, EggCCError> {
+    ) -> Result<(Interpretable, Duration), EggCCError> {
         // Make a unique name for this test running bril llvm
         // so we don't have conflicts in /tmp
         let unique_name = format!("{}_{}_{}", self.name(), optimize_egglog, llvm_level);
@@ -1120,6 +1135,7 @@ impl Run {
         }
 
         // Now, run the llvm optimizer and generate optimized llvm
+        let llvm_time_start = Instant::now();
         expect_command_success(
             Command::new(clang_cmd)
                 .arg(processed.clone())
@@ -1133,6 +1149,7 @@ impl Run {
                 .arg(optimized.clone()),
             "failed to optimize llvm ir",
         );
+        let llvm_time = llvm_time_start.elapsed();
 
         // Lower the optimized LLVM but don't do target-specific optimizations besides register allocation
         // We use O0 and disable debug info
@@ -1170,9 +1187,12 @@ impl Run {
         );
 
         if add_timing {
-            Ok(Interpretable::CycleMeasuringExecutable { executable })
+            Ok((
+                Interpretable::CycleMeasuringExecutable { executable },
+                llvm_time,
+            ))
         } else {
-            Ok(Interpretable::Executable { executable })
+            Ok((Interpretable::Executable { executable }, llvm_time))
         }
     }
 }