From 4dae0538d34ef5ae35dd3583abb1a7e1944fe8d6 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Juli=C3=A1n=20Gonz=C3=A1lez=20Calder=C3=B3n?= Date: Fri, 27 Sep 2024 18:56:30 -0300 Subject: [PATCH 1/4] Add mlir compilation time --- src/executor/contract.rs | 8 ++++++++ 1 file changed, 8 insertions(+) diff --git a/src/executor/contract.rs b/src/executor/contract.rs index 5d8e3db51..d019c4b7a 100644 --- a/src/executor/contract.rs +++ b/src/executor/contract.rs @@ -63,8 +63,10 @@ use std::{ path::{Path, PathBuf}, ptr::NonNull, sync::Arc, + time::Instant, }; use tempfile::NamedTempFile; +use tracing::info; /// Please look at the [module level docs](self). #[derive(Educe, Clone)] @@ -104,9 +106,15 @@ impl AotContractExecutor { /// a temporary file an deleted when dropped. /// If you loaded a ContractExecutor using [`load`] then it will not be treated as a temp file. pub fn new(sierra_program: &Program, opt_level: OptLevel) -> Result { + info!("starting mlir compilation"); + let pre_mlir_compilation_instant = Instant::now(); + let native_context = NativeContext::new(); let module = native_context.compile(sierra_program, true)?; + let mlir_compilation_time = pre_mlir_compilation_instant.elapsed().as_millis(); + info!(time = mlir_compilation_time, "mlir compilation finished"); + let NativeModule { module, registry, From 8bde3032b13938614b43706ac95473dfb0f3dbf5 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Juli=C3=A1n=20Gonz=C3=A1lez=20Calder=C3=B3n?= Date: Mon, 30 Sep 2024 11:08:34 -0300 Subject: [PATCH 2/4] Add time to llvm compilation and object linking --- src/executor/contract.rs | 11 +++++++++-- 1 file changed, 9 insertions(+), 2 deletions(-) diff --git a/src/executor/contract.rs b/src/executor/contract.rs index d019c4b7a..1153fd4f8 100644 --- a/src/executor/contract.rs +++ b/src/executor/contract.rs @@ -108,10 +108,8 @@ impl AotContractExecutor { pub fn new(sierra_program: &Program, opt_level: OptLevel) -> Result { info!("starting mlir compilation"); let pre_mlir_compilation_instant = Instant::now(); - let native_context = NativeContext::new(); let module = native_context.compile(sierra_program, true)?; - let mlir_compilation_time = pre_mlir_compilation_instant.elapsed().as_millis(); info!(time = mlir_compilation_time, "mlir compilation finished"); @@ -171,8 +169,17 @@ impl AotContractExecutor { .keep() .expect("can only fail on windows"); + info!("starting llvm compilation"); + let pre_llvm_compilation_instant = Instant::now(); let object_data = crate::module_to_object(&module, opt_level)?; + let llvm_compilation_time = pre_llvm_compilation_instant.elapsed().as_millis(); + info!(time = llvm_compilation_time, "llvm compilation finished"); + + info!("starting object linking"); + let pre_object_linking_instant = Instant::now(); crate::object_to_shared_lib(&object_data, &library_path)?; + let object_linking_time = pre_object_linking_instant.elapsed().as_millis(); + info!(time = object_linking_time, "object linking finished"); Ok(Self { library: Arc::new(unsafe { Library::new(&library_path)? }), From 9d63d2ed1e429d114df8bde1cee6e889a382531b Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Juli=C3=A1n=20Gonz=C3=A1lez=20Calder=C3=B3n?= Date: Mon, 30 Sep 2024 14:22:07 -0300 Subject: [PATCH 3/4] Use finer grained timers --- src/context.rs | 16 +++++++++++++++- src/executor/contract.rs | 15 --------------- src/ffi.rs | 25 +++++++++++++++++++++++++ 3 files changed, 40 insertions(+), 16 deletions(-) diff --git a/src/context.rs b/src/context.rs index c6b249219..bb2c65821 100644 --- a/src/context.rs +++ b/src/context.rs @@ -33,7 +33,8 @@ use mlir_sys::{ mlirLLVMDIModuleAttrGet, MlirLLVMDIEmissionKind_MlirLLVMDIEmissionKindFull, MlirLLVMDINameTableKind_MlirLLVMDINameTableKindDefault, }; -use std::sync::OnceLock; +use std::{sync::OnceLock, time::Instant}; +use tracing::info; /// Context of IRs, dialects and passes for Cairo programs compilation. #[derive(Debug, Eq, PartialEq)] @@ -70,6 +71,9 @@ impl NativeContext { program: &Program, ignore_debug_names: bool, ) -> Result { + info!("starting sierra to mlir compilation"); + let pre_sierra_compilation_instant = Instant::now(); + static INITIALIZED: OnceLock<()> = OnceLock::new(); INITIALIZED.get_or_init(|| unsafe { LLVM_InitializeAllTargets(); @@ -181,6 +185,12 @@ impl NativeContext { ignore_debug_names, )?; + let sierra_compilation_time = pre_sierra_compilation_instant.elapsed().as_millis(); + info!( + time = sierra_compilation_time, + "sierra to mlir compilation finished" + ); + if let Ok(x) = std::env::var("NATIVE_DEBUG_DUMP") { if x == "1" || x == "true" { std::fs::write("dump-prepass.mlir", module.as_operation().to_string()) @@ -202,7 +212,11 @@ impl NativeContext { } } + info!("starting mlir passes"); + let pre_passes_instant = Instant::now(); run_pass_manager(&self.context, &mut module)?; + let passes_time = pre_passes_instant.elapsed().as_millis(); + info!(time = passes_time, "mlir passes finished"); if let Ok(x) = std::env::var("NATIVE_DEBUG_DUMP") { if x == "1" || x == "true" { diff --git a/src/executor/contract.rs b/src/executor/contract.rs index 1153fd4f8..5d8e3db51 100644 --- a/src/executor/contract.rs +++ b/src/executor/contract.rs @@ -63,10 +63,8 @@ use std::{ path::{Path, PathBuf}, ptr::NonNull, sync::Arc, - time::Instant, }; use tempfile::NamedTempFile; -use tracing::info; /// Please look at the [module level docs](self). #[derive(Educe, Clone)] @@ -106,12 +104,8 @@ impl AotContractExecutor { /// a temporary file an deleted when dropped. /// If you loaded a ContractExecutor using [`load`] then it will not be treated as a temp file. pub fn new(sierra_program: &Program, opt_level: OptLevel) -> Result { - info!("starting mlir compilation"); - let pre_mlir_compilation_instant = Instant::now(); let native_context = NativeContext::new(); let module = native_context.compile(sierra_program, true)?; - let mlir_compilation_time = pre_mlir_compilation_instant.elapsed().as_millis(); - info!(time = mlir_compilation_time, "mlir compilation finished"); let NativeModule { module, @@ -169,17 +163,8 @@ impl AotContractExecutor { .keep() .expect("can only fail on windows"); - info!("starting llvm compilation"); - let pre_llvm_compilation_instant = Instant::now(); let object_data = crate::module_to_object(&module, opt_level)?; - let llvm_compilation_time = pre_llvm_compilation_instant.elapsed().as_millis(); - info!(time = llvm_compilation_time, "llvm compilation finished"); - - info!("starting object linking"); - let pre_object_linking_instant = Instant::now(); crate::object_to_shared_lib(&object_data, &library_path)?; - let object_linking_time = pre_object_linking_instant.elapsed().as_millis(); - info!(time = object_linking_time, "object linking finished"); Ok(Self { library: Arc::new(unsafe { Library::new(&library_path)? }), diff --git a/src/ffi.rs b/src/ffi.rs index a53a1343e..bf48e5167 100644 --- a/src/ffi.rs +++ b/src/ffi.rs @@ -35,8 +35,10 @@ use std::{ path::Path, ptr::{addr_of_mut, null_mut}, sync::OnceLock, + time::Instant, }; use tempfile::NamedTempFile; +use tracing::info; /// For any `!llvm.struct<...>` type, return the MLIR type of the field at the requested index. pub fn get_struct_field_type_at<'c>(r#type: &Type<'c>, index: usize) -> Type<'c> { @@ -109,7 +111,11 @@ pub fn module_to_object(module: &Module<'_>, opt_level: OptLevel) -> Result, opt_level: OptLevel) -> Result 1, // https://github.com/llvm/llvm-project/issues/107198 }; let passes = CString::new(format!("default")).unwrap(); + + info!("starting llvm passes"); + let pre_passes_instant = Instant::now(); let error = LLVMRunPasses(llvm_module, passes.as_ptr(), machine, opts); + let passes_time = pre_passes_instant.elapsed().as_millis(); + info!(time = passes_time, "llvm passes finished"); + if !error.is_null() { let msg = LLVMGetErrorMessage(error); let msg = CStr::from_ptr(msg); @@ -167,6 +179,8 @@ pub fn module_to_object(module: &Module<'_>, opt_level: OptLevel) -> Result = MaybeUninit::uninit(); + info!("starting llvm to object compilation"); + let pre_llvm_compilation_instant = Instant::now(); let ok = LLVMTargetMachineEmitToMemoryBuffer( machine, llvm_module, @@ -174,6 +188,11 @@ pub fn module_to_object(module: &Module<'_>, opt_level: OptLevel) -> Result Result<()> }; let mut linker = std::process::Command::new("ld"); + + info!("starting linking"); + let pre_linking_instant = Instant::now(); let proc = linker.args(args.iter().map(|x| x.as_ref())).output()?; + let linking_time = pre_linking_instant.elapsed().as_millis(); + info!(time = linking_time, "linking finished"); + if proc.status.success() { Ok(()) } else { From 90575b5c341764023ba783a5aad40d6a91480ddd Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Juli=C3=A1n=20Gonz=C3=A1lez=20Calder=C3=B3n?= Date: Thu, 10 Oct 2024 17:08:37 -0300 Subject: [PATCH 4/4] Change info to trace --- src/context.rs | 10 +++++----- src/ffi.rs | 18 +++++++++--------- 2 files changed, 14 insertions(+), 14 deletions(-) diff --git a/src/context.rs b/src/context.rs index bb2c65821..f868c0faa 100644 --- a/src/context.rs +++ b/src/context.rs @@ -34,7 +34,7 @@ use mlir_sys::{ MlirLLVMDINameTableKind_MlirLLVMDINameTableKindDefault, }; use std::{sync::OnceLock, time::Instant}; -use tracing::info; +use tracing::trace; /// Context of IRs, dialects and passes for Cairo programs compilation. #[derive(Debug, Eq, PartialEq)] @@ -71,7 +71,7 @@ impl NativeContext { program: &Program, ignore_debug_names: bool, ) -> Result { - info!("starting sierra to mlir compilation"); + trace!("starting sierra to mlir compilation"); let pre_sierra_compilation_instant = Instant::now(); static INITIALIZED: OnceLock<()> = OnceLock::new(); @@ -186,7 +186,7 @@ impl NativeContext { )?; let sierra_compilation_time = pre_sierra_compilation_instant.elapsed().as_millis(); - info!( + trace!( time = sierra_compilation_time, "sierra to mlir compilation finished" ); @@ -212,11 +212,11 @@ impl NativeContext { } } - info!("starting mlir passes"); + trace!("starting mlir passes"); let pre_passes_instant = Instant::now(); run_pass_manager(&self.context, &mut module)?; let passes_time = pre_passes_instant.elapsed().as_millis(); - info!(time = passes_time, "mlir passes finished"); + trace!(time = passes_time, "mlir passes finished"); if let Ok(x) = std::env::var("NATIVE_DEBUG_DUMP") { if x == "1" || x == "true" { diff --git a/src/ffi.rs b/src/ffi.rs index bf48e5167..3e9c84542 100644 --- a/src/ffi.rs +++ b/src/ffi.rs @@ -38,7 +38,7 @@ use std::{ time::Instant, }; use tempfile::NamedTempFile; -use tracing::info; +use tracing::trace; /// For any `!llvm.struct<...>` type, return the MLIR type of the field at the requested index. pub fn get_struct_field_type_at<'c>(r#type: &Type<'c>, index: usize) -> Type<'c> { @@ -111,11 +111,11 @@ pub fn module_to_object(module: &Module<'_>, opt_level: OptLevel) -> Result, opt_level: OptLevel) -> Result")).unwrap(); - info!("starting llvm passes"); + trace!("starting llvm passes"); let pre_passes_instant = Instant::now(); let error = LLVMRunPasses(llvm_module, passes.as_ptr(), machine, opts); let passes_time = pre_passes_instant.elapsed().as_millis(); - info!(time = passes_time, "llvm passes finished"); + trace!(time = passes_time, "llvm passes finished"); if !error.is_null() { let msg = LLVMGetErrorMessage(error); @@ -179,7 +179,7 @@ pub fn module_to_object(module: &Module<'_>, opt_level: OptLevel) -> Result = MaybeUninit::uninit(); - info!("starting llvm to object compilation"); + trace!("starting llvm to object compilation"); let pre_llvm_compilation_instant = Instant::now(); let ok = LLVMTargetMachineEmitToMemoryBuffer( machine, @@ -189,7 +189,7 @@ pub fn module_to_object(module: &Module<'_>, opt_level: OptLevel) -> Result Result<()> let mut linker = std::process::Command::new("ld"); - info!("starting linking"); + trace!("starting linking"); let pre_linking_instant = Instant::now(); let proc = linker.args(args.iter().map(|x| x.as_ref())).output()?; let linking_time = pre_linking_instant.elapsed().as_millis(); - info!(time = linking_time, "linking finished"); + trace!(time = linking_time, "linking finished"); if proc.status.success() { Ok(())