#![allow(unused_variables)]
use crate::{debug_log, internal_doc, safe_alloc, ProfileError, ProfileResult};
use chrono::{DateTime, Local, NaiveDateTime, TimeZone};
use parking_lot::{Mutex, RwLock};
use std::{
collections::{BTreeSet, HashMap},
env,
fmt::{Display, Formatter},
fs::File,
io::BufWriter,
path::PathBuf,
str::FromStr,
sync::atomic::{AtomicU8, Ordering},
time::{Duration, Instant},
};
use thag_common::{re, static_lazy};
#[cfg(feature = "time_profiling")]
use std::collections::HashSet;
#[cfg(feature = "full_profiling")]
use crate::{
fn_name,
mem_attribution::{deregister_profile, get_next_profile_id, register_profile},
mem_tracking::{
activate_task, create_memory_task, TaskGuard, TaskMemoryContext, TASK_PATH_REGISTRY,
},
};
#[cfg(feature = "time_profiling")]
use backtrace::{resolve_frame, trace};
#[cfg(feature = "time_profiling")]
use crate::{file_stem_from_path_str, flush_debug_log, get_base_location, warn_once};
#[cfg(feature = "time_profiling")]
use parking_lot::ReentrantMutex;
#[cfg(feature = "time_profiling")]
use std::{
convert::Into,
fs::OpenOptions,
io::{BufRead, BufReader, Write},
path::Path,
sync::{
atomic::{AtomicBool, AtomicU64},
OnceLock,
},
time::SystemTime,
};
#[cfg(feature = "full_profiling")]
use regex::Regex;
#[cfg(feature = "full_profiling")]
use std::sync::{atomic::AtomicUsize, Arc};
#[cfg(feature = "time_profiling")]
static PROFILING_STATE: AtomicBool = AtomicBool::new(false);
#[internal_doc]
#[cfg(feature = "time_profiling")]
pub static PROFILING_MUTEX: ReentrantMutex<()> = ReentrantMutex::new(());
#[allow(dead_code)]
#[derive(Debug, Clone, Copy, PartialEq, Eq)]
pub struct ProfileCapability(pub u8);
#[allow(dead_code)]
impl ProfileCapability {
pub const NONE: Self = Self(0);
pub const TIME: Self = Self(1);
pub const MEMORY: Self = Self(2);
pub const BOTH: Self = Self(3);
#[must_use]
pub const fn available() -> Self {
#[cfg(all(feature = "time_profiling", not(feature = "full_profiling")))]
{
Self::TIME
}
#[cfg(feature = "full_profiling")]
{
Self::BOTH
}
#[cfg(all(not(feature = "time_profiling"), not(feature = "full_profiling")))]
{
Self::NONE
}
}
#[must_use]
pub const fn supports(&self, profile_type: ProfileType) -> bool {
match profile_type {
ProfileType::Time => (self.0 & Self::TIME.0) == Self::TIME.0,
ProfileType::Memory => (self.0 & Self::MEMORY.0) == Self::MEMORY.0,
ProfileType::Both => (self.0 & Self::BOTH.0) == Self::BOTH.0,
ProfileType::None => true,
}
}
#[must_use]
pub const fn from_profile_type(profile_type: ProfileType) -> Self {
match profile_type {
ProfileType::Time => Self::TIME,
ProfileType::Memory => Self::MEMORY,
ProfileType::Both => Self::BOTH,
ProfileType::None => Self::NONE,
}
}
#[must_use]
pub const fn intersection(self, profile_type: ProfileType) -> Self {
Self(self.0 & Self::from_profile_type(profile_type).0)
}
}
#[cfg(debug_assertions)]
const fn is_valid_profile_type(profile_type: ProfileType) -> bool {
ProfileCapability::available().supports(profile_type)
}
#[cfg(all(feature = "time_profiling", not(test)))]
const PROFILING_FEATURE: bool = true;
#[allow(dead_code)]
#[cfg(all(feature = "time_profiling", test))]
const PROFILING_FEATURE: bool = false;
static GLOBAL_PROFILE_TYPE: AtomicU8 = AtomicU8::new(0);
static PROFILE_CONFIG_CACHE: Mutex<Option<ProfileConfiguration>> = Mutex::new(None);
#[must_use]
pub fn get_profile_config() -> ProfileConfiguration {
{
let cache = PROFILE_CONFIG_CACHE.lock();
if let Some(config) = &*cache {
return config.clone();
}
}
let config = parse_env_profile_config().expect("Expected environment variable `THAG_PROFILER={time|memory|both|none},[dir],{none}quiet|announce}[,true|false]`");
let mut cache = PROFILE_CONFIG_CACHE.lock();
*cache = Some(config.clone());
config
}
#[internal_doc]
pub fn clear_profile_config_cache() {
let mut cache = PROFILE_CONFIG_CACHE.lock();
*cache = None;
}
#[internal_doc]
pub fn set_profile_config(config: ProfileConfiguration) {
let mut cache = PROFILE_CONFIG_CACHE.lock();
*cache = Some(config);
}
#[allow(dead_code)]
#[derive(Debug, Default, Clone, Copy, PartialEq, Eq)]
pub enum DebugLevel {
#[default]
None,
Quiet,
Announce,
}
impl Display for DebugLevel {
fn fmt(&self, f: &mut Formatter<'_>) -> std::fmt::Result {
match self {
Self::None => write!(f, "none"),
Self::Quiet => write!(f, "quiet"),
Self::Announce => write!(f, "announce"),
}
}
}
impl FromStr for DebugLevel {
type Err = String;
fn from_str(s: &str) -> Result<Self, Self::Err> {
match s.trim().to_lowercase().as_str() {
"none" => Ok(Self::None),
"quiet" => Ok(Self::Quiet),
"announce" => Ok(Self::Announce),
_ => Err(format!(
"Invalid debug log type '{s}'. Expected 'none', 'quiet', or 'announce'"
)),
}
}
}
#[derive(Debug, Clone)]
#[internal_doc]
pub struct ProfileConfiguration {
enabled: bool,
profile_type: Option<ProfileType>,
output_dir: Option<PathBuf>,
debug_level: Option<DebugLevel>,
detailed_memory: bool,
}
impl TryFrom<&[&str]> for ProfileConfiguration {
type Error = ProfileError;
fn try_from(value: &[&str]) -> Result<Self, Self::Error> {
let mut errors = Vec::new();
let profile_type = {
let profile_type_str = value.first().map_or("", |s| *s).trim();
match profile_type_str.parse::<ProfileType>() {
Ok(val) => {
Some(val)
}
Err(e) => {
errors.push(e);
None
}
}
};
let output_dir = if value.get(1).map_or("", |s| *s).trim().is_empty() {
Some(PathBuf::from(".")) } else {
Some(PathBuf::from(value.get(1).unwrap().trim()))
};
let debug_level = if value.get(2).map_or("none", |s| *s).trim().is_empty() {
errors.push(
"Third element (debug log) is empty. Expected 'none', 'quiet', or 'announce'"
.to_string(),
);
None
} else {
match value.get(2).unwrap_or(&"none").parse::<DebugLevel>() {
Ok(val) => Some(val),
Err(e) => {
errors.push(e);
None
}
}
};
let detailed_memory = value.get(3).is_some_and(|val| if val.trim().is_empty() {
false } else if let Ok(val) = val.trim().parse::<bool>() {
if val
&& profile_type
.as_ref().is_some_and(|pt| *pt == ProfileType::Time)
{
errors.push(
"Detailed memory profiling can only be enabled with profile_type=memory or profile_type=both"
.to_string(),
);
false
} else {
val
}
} else {
errors.push(format!(
"Failed to parse '{val}' as boolean for detailed memory flag. Expected 'true' or 'false'"
));
false
});
if !errors.is_empty() {
return Err(ProfileError::General(errors.join("\n")));
}
Ok(Self {
enabled: true, profile_type,
output_dir,
debug_level,
detailed_memory,
})
}
}
impl ProfileConfiguration {
#[must_use]
pub const fn is_enabled(&self) -> bool {
self.enabled
}
#[must_use]
pub const fn profile_type(&self) -> Option<ProfileType> {
self.profile_type
}
#[allow(clippy::missing_const_for_fn)]
pub fn set_profile_type(&mut self, profile_type: Option<ProfileType>) {
self.profile_type = profile_type;
}
#[must_use]
pub const fn debug_level(&self) -> Option<DebugLevel> {
self.debug_level
}
#[must_use]
pub const fn is_detailed_memory(&self) -> bool {
self.detailed_memory
}
}
impl Default for ProfileConfiguration {
#[cfg(feature = "time_profiling")]
fn default() -> Self {
use std::env::current_dir;
#[cfg(feature = "full_profiling")]
let profile_type = Some(ProfileType::Both);
#[cfg(not(feature = "full_profiling"))]
let profile_type = Some(ProfileType::Time);
Self {
enabled: true,
profile_type,
output_dir: Some(current_dir().expect("Failed to determine current directory")),
debug_level: Some(DebugLevel::None),
detailed_memory: false,
}
}
#[cfg(not(feature = "time_profiling"))]
fn default() -> Self {
Self {
enabled: false,
profile_type: None,
output_dir: None,
debug_level: None,
detailed_memory: false,
}
}
}
#[internal_doc]
pub fn parse_env_profile_config() -> ProfileResult<ProfileConfiguration> {
let Ok(env_var) = env::var("THAG_PROFILER") else {
let profile_type = if cfg!(feature = "full_profiling") {
Some(ProfileType::Both)
} else if cfg!(feature = "time_profiling") {
Some(ProfileType::Time)
} else {
None
};
return Ok(ProfileConfiguration {
enabled: false,
profile_type,
output_dir: None,
debug_level: None,
detailed_memory: false,
});
};
let parts: Vec<&str> = env_var.split(',').collect();
ProfileConfiguration::try_from(parts.as_slice())
}
impl Display for ProfileConfiguration {
fn fmt(&self, f: &mut Formatter<'_>) -> std::fmt::Result {
writeln!(f, "Profile Config:")?;
writeln!(f, " Enabled: {}", self.enabled)?;
match &self.profile_type {
Some(pt) => writeln!(f, " Profile Type: {pt:?}")?,
None => writeln!(f, " Profile Type: none")?,
}
match &self.output_dir {
Some(dir) => writeln!(f, " Output Directory: {}", dir.display())?,
None => writeln!(f, " Output Directory: none")?,
}
match &self.debug_level {
Some(log) => writeln!(f, " Debug Log: {log:?}")?,
None => writeln!(f, " Debug Log: none")?,
}
write!(f, " Detailed Memory: {:?}", self.detailed_memory)
}
}
#[must_use]
pub fn get_debug_level() -> DebugLevel {
get_profile_config().debug_level.unwrap_or_default()
}
#[must_use]
pub fn is_detailed_memory() -> bool {
get_profile_config().detailed_memory
}
#[must_use]
pub fn get_config_profile_type() -> ProfileType {
get_profile_config().profile_type.unwrap_or_default()
}
static PROFILED_FUNCTIONS: std::sync::LazyLock<RwLock<HashMap<String, String>>> =
std::sync::LazyLock::new(|| RwLock::new(HashMap::new()));
static_lazy! {
ProfilePaths: ProfileFilePaths = {
let script_path = std::env::current_exe()
.unwrap_or_else(|_| PathBuf::from("unknown"));
let script_stem = script_path
.file_stem()
.and_then(|s| s.to_str())
.unwrap_or("unknown");
let timestamp = Local::now().format("%Y%m%d-%H%M%S").to_string();
let base = format!("{script_stem}-{timestamp}");
let mut debug_log_path = std::env::temp_dir();
debug_log_path.push("thag_profiler");
std::fs::create_dir_all(&debug_log_path).ok();
debug_log_path.push(format!("{base}-debug.log"));
ProfileFilePaths {
time: format!("{base}.folded"),
inclusive_time: format!("{base}-inclusive.folded"),
profraw: format!("{base}.profraw"),
memory: format!("{base}-memory.folded"),
debug_log: debug_log_path.to_string_lossy().to_string(),
executable_stem: script_stem.to_string(),
timestamp,
memory_detail: format!("{base}-memory_detail.folded"),
memory_detail_dealloc: format!("{base}-memory_detail_dealloc.folded")
}
}
}
static_lazy! {
TimeProfileFile: Mutex<Option<BufWriter<File>>> = Mutex::new(None)
}
static_lazy! {
InclusiveTimeProfileFile: Mutex<Option<BufWriter<File>>> = Mutex::new(None)
}
static_lazy! {
ProfrawProfileFile: Mutex<Option<BufWriter<File>>> = Mutex::new(None)
}
static_lazy! {
MemoryProfileFile: Mutex<Option<BufWriter<File>>> = Mutex::new(None)
}
static_lazy! {
MemoryDeallocFile: Mutex<Option<BufWriter<File>>> = Mutex::new(None)
}
#[cfg(feature = "full_profiling")]
static_lazy! {
MemoryDetailFile: Mutex<Option<BufWriter<File>>> = Mutex::new(None)
}
#[cfg(feature = "full_profiling")]
static_lazy! {
MemoryDetailDeallocFile: Mutex<Option<BufWriter<File>>> = Mutex::new(None)
}
#[cfg(feature = "time_profiling")]
static START_TIME: AtomicU64 = AtomicU64::new(0);
#[derive(Clone)]
#[allow(dead_code)]
pub struct ProfileFilePaths {
time: String,
inclusive_time: String, profraw: String, memory: String,
memory_detail: String,
memory_detail_dealloc: String,
pub debug_log: String,
pub executable_stem: String,
pub timestamp: String,
}
#[cfg(feature = "time_profiling")]
pub fn get_time_path() -> ProfileResult<&'static str> {
struct TimePathHolder;
impl TimePathHolder {
fn get() -> ProfileResult<&'static str> {
static PATH_RESULT: OnceLock<Result<String, ProfileError>> = OnceLock::new();
let result = PATH_RESULT.get_or_init(|| {
let paths = ProfilePaths::get();
let config = get_profile_config();
let path = if let Some(dir) = &config.output_dir {
let dir_path = PathBuf::from(dir);
if !dir_path.exists() {
match std::fs::create_dir_all(&dir_path) {
Ok(()) => {}
Err(e) => return Err(ProfileError::from(e)),
}
}
let time_file =
dir_path.join(paths.time.split('/').next_back().unwrap_or(&paths.time));
time_file.to_string_lossy().to_string()
} else {
paths.time.clone()
};
Ok(path)
});
match result {
Ok(s) => Ok(Box::leak(s.clone().into_boxed_str())),
Err(e) => Err(e.clone()),
}
}
}
TimePathHolder::get()
}
#[cfg(feature = "full_profiling")]
pub fn get_memory_detail_path() -> ProfileResult<&'static str> {
struct MemoryDetailPathHolder;
impl MemoryDetailPathHolder {
fn get() -> ProfileResult<&'static str> {
static PATH_RESULT: OnceLock<Result<String, ProfileError>> = OnceLock::new();
let result = PATH_RESULT.get_or_init(|| {
let paths = ProfilePaths::get();
let config = get_profile_config();
let path = if let Some(dir) = &config.output_dir {
let dir_path = PathBuf::from(dir);
if !dir_path.exists() {
match std::fs::create_dir_all(&dir_path) {
Ok(()) => {}
Err(e) => return Err(ProfileError::from(e)),
}
}
let memory_detail_file = dir_path.join(
paths
.memory_detail
.split('/')
.next_back()
.unwrap_or(&paths.memory_detail),
);
memory_detail_file.to_string_lossy().to_string()
} else {
paths.memory_detail.clone()
};
Ok(path)
});
match result {
Ok(s) => Ok(Box::leak(s.clone().into_boxed_str())),
Err(e) => Err(e.clone()),
}
}
}
MemoryDetailPathHolder::get()
}
#[cfg(feature = "full_profiling")]
pub fn get_memory_detail_dealloc_path() -> ProfileResult<&'static str> {
struct MemoryDetailDeallocPathHolder;
impl MemoryDetailDeallocPathHolder {
fn get() -> ProfileResult<&'static str> {
static PATH_RESULT: OnceLock<Result<String, ProfileError>> = OnceLock::new();
let result = PATH_RESULT.get_or_init(|| {
let paths = ProfilePaths::get();
let config = get_profile_config();
let path = if let Some(dir) = &config.output_dir {
let dir_path = PathBuf::from(dir);
if !dir_path.exists() {
match std::fs::create_dir_all(&dir_path) {
Ok(()) => {}
Err(e) => return Err(ProfileError::from(e)),
}
}
let memory_detail_dealloc_file = dir_path.join(
paths
.memory_detail_dealloc
.split('/')
.next_back()
.unwrap_or(&paths.memory_detail_dealloc),
);
memory_detail_dealloc_file.to_string_lossy().to_string()
} else {
paths.memory_detail_dealloc.clone()
};
Ok(path)
});
match result {
Ok(s) => Ok(Box::leak(s.clone().into_boxed_str())),
Err(e) => Err(e.clone()),
}
}
}
MemoryDetailDeallocPathHolder::get()
}
#[cfg(feature = "full_profiling")]
pub fn get_memory_path() -> ProfileResult<&'static str> {
struct MemoryPathHolder;
impl MemoryPathHolder {
fn get() -> ProfileResult<&'static str> {
static PATH_RESULT: OnceLock<Result<String, ProfileError>> = OnceLock::new();
let result = PATH_RESULT.get_or_init(|| {
let paths = ProfilePaths::get();
let config = get_profile_config();
let path = if let Some(dir) = &config.output_dir {
let dir_path = PathBuf::from(dir);
if !dir_path.exists() {
match std::fs::create_dir_all(&dir_path) {
Ok(()) => {}
Err(e) => return Err(ProfileError::from(e)),
}
}
let memory_file =
dir_path.join(paths.memory.split('/').next_back().unwrap_or(&paths.memory));
memory_file.to_string_lossy().to_string()
} else {
paths.memory.clone()
};
Ok(path)
});
match result {
Ok(s) => Ok(Box::leak(s.clone().into_boxed_str())),
Err(e) => Err(e.clone()),
}
}
}
MemoryPathHolder::get()
}
#[cfg(all(feature = "time_profiling", not(feature = "full_profiling")))]
fn initialize_profile_files(profile_type: ProfileType) -> ProfileResult<()> {
let available_caps = ProfileCapability::available();
if !available_caps.supports(profile_type) {
if matches!(profile_type, ProfileType::Memory | ProfileType::Both) {
panic!(
"Profile type `{profile_type:?}` requested but feature `full_profiling` is not enabled",
);
}
if profile_type == ProfileType::None {
debug_log!("ProfileType::None selected: no profiling will be done");
return Ok(());
}
}
if matches!(profile_type, ProfileType::Time | ProfileType::Both) {
let paths = ProfilePaths::get();
let profraw_path = &paths.profraw;
ProfrawProfileFile::init();
initialize_file(profraw_path, ProfrawProfileFile::get())?;
debug_log!("Profraw profile will be written to {profraw_path}");
let inclusive_time_path = &paths.inclusive_time;
InclusiveTimeProfileFile::init();
initialize_file(inclusive_time_path, InclusiveTimeProfileFile::get())?;
debug_log!("Inclusive time profile will be written to {inclusive_time_path}");
}
flush_debug_log();
Ok(())
}
#[cfg(feature = "full_profiling")]
fn initialize_profile_files(profile_type: ProfileType) -> ProfileResult<bool> {
let available_caps = ProfileCapability::available();
debug_log!("In initialize_profile_files for profile_type={profile_type:?}");
if profile_type == ProfileType::None {
debug_log!("ProfileType::None selected: no profiling will be done");
flush_debug_log();
return Ok(true);
}
let actual_caps = available_caps.intersection(profile_type);
if (actual_caps.0 & ProfileCapability::TIME.0) != 0 {
let paths = ProfilePaths::get();
let profraw_path = &paths.profraw;
ProfrawProfileFile::init();
initialize_file(profraw_path, ProfrawProfileFile::get())?;
debug_log!("Profraw profile will be written to {profraw_path}");
let inclusive_time_path = &paths.inclusive_time;
InclusiveTimeProfileFile::init();
initialize_file(inclusive_time_path, InclusiveTimeProfileFile::get())?;
debug_log!("Inclusive time profile will be written to {inclusive_time_path}");
let time_path = get_time_path()?;
debug_log!("Time profile will be written to {time_path}");
}
if (actual_caps.0 & ProfileCapability::MEMORY.0) != 0 {
let memory_path = get_memory_path()?;
let memory_detail_path = get_memory_detail_path()?;
let memory_detail_dealloc_path = get_memory_detail_dealloc_path()?;
MemoryProfileFile::init();
initialize_file(memory_path, MemoryProfileFile::get())?;
debug_log!("Memory profile will be written to {memory_path}");
if is_detailed_memory() {
MemoryDetailFile::init();
initialize_file(memory_detail_path, MemoryDetailFile::get())?;
debug_log!("Memory detail will be written to {memory_detail_path}");
MemoryDetailDeallocFile::init();
initialize_file(memory_detail_dealloc_path, MemoryDetailDeallocFile::get())?;
debug_log!("Memory detail dealloc will be written to {memory_detail_dealloc_path}");
}
}
flush_debug_log();
Ok(true)
}
#[cfg(feature = "time_profiling")]
fn initialize_file(
file_path: &str,
file: &parking_lot::lock_api::Mutex<parking_lot::RawMutex, Option<BufWriter<File>>>,
) -> Result<(), ProfileError> {
*file.lock() = None;
initialize_profile_file(file_path)?;
Ok(())
}
pub fn get_global_profile_type() -> ProfileType {
let global_value = GLOBAL_PROFILE_TYPE.load(Ordering::SeqCst);
match global_value {
0 => {
let profile_type = get_profile_config()
.profile_type
.unwrap_or(ProfileType::None);
set_global_profile_type(profile_type);
profile_type
}
1 => ProfileType::Time,
2 => ProfileType::Memory,
3 => ProfileType::Both,
_ => {
debug_log!("Unexpected GLOBAL_PROFILE_TYPE value: {}", global_value);
get_profile_config()
.profile_type
.unwrap_or(ProfileType::None)
}
}
}
#[allow(clippy::missing_panics_doc)]
#[internal_doc]
pub fn set_global_profile_type(profile_type: ProfileType) {
#[cfg(all(debug_assertions, feature = "full_profiling"))]
assert!(
is_valid_profile_type(profile_type),
"Invalid profile type {profile_type:?} for feature set"
);
#[cfg(all(debug_assertions, not(feature = "full_profiling")))]
if profile_type == ProfileType::Memory {
assert!(
!is_valid_profile_type(profile_type),
"Profile type {profile_type:?} should not be valid for feature set"
);
} else {
assert!(
is_valid_profile_type(profile_type),
"Invalid profile type {profile_type:?} for feature set"
);
}
let value = ProfileCapability::from_profile_type(profile_type).0;
GLOBAL_PROFILE_TYPE.store(value, Ordering::SeqCst);
}
#[cfg(feature = "time_profiling")]
pub(crate) fn enable_profiling(
enabled: bool,
maybe_profile_type: Option<ProfileType>,
) -> ProfileResult<()> {
let _guard = PROFILING_MUTEX.lock();
#[cfg(test)]
{
debug_log!("Unit test: Resetting profile config to ensure latest env vars are used");
clear_profile_config_cache();
}
let config = get_profile_config();
if enabled != config.enabled {
debug_log!(
"Caution: `enable_profiling` attribute or function `enabled={enabled}` call overriding configured value"
);
}
if enabled {
debug_log!(
"maybe_profile_type={maybe_profile_type:?}, get_config_profile_type={:?}",
get_config_profile_type()
);
if PROFILING_STATE.load(Ordering::SeqCst) {
return Err(ProfileError::General(
"Can't enable profiling: already enabled".to_string(),
));
}
let final_profile_type = if let Some(profile_type) = maybe_profile_type {
debug_log!(
"enable_profiling: Using provided profile_type={:?}",
profile_type
);
profile_type
} else {
let config_profile_type = get_config_profile_type();
debug_log!(
"enable_profiling: Using config_profile_type={:?}",
config_profile_type
);
if !cfg!(feature = "full_profiling") && config_profile_type != ProfileType::Time {
debug_log!(
"enable_profiling: Memory profiling not allowed without full_profiling feature"
);
return Err(ProfileError::General(
"Memory profiling not allowed since feature `full_profiling` is not specified"
.to_string(),
));
}
config_profile_type
};
set_global_profile_type(final_profile_type);
debug_log!("Set global profile type to {:?}", get_global_profile_type());
let Ok(now) = u64::try_from(
SystemTime::now()
.duration_since(SystemTime::UNIX_EPOCH)
.unwrap_or_default()
.as_micros(),
) else {
return Err(ProfileError::General("Time value too large".into()));
};
START_TIME.store(now, Ordering::SeqCst);
initialize_profile_files(final_profile_type)?;
}
PROFILING_STATE.store(enabled, Ordering::SeqCst);
debug_log!("Profiling state set to {}", enabled);
Ok(())
}
#[allow(clippy::missing_const_for_fn)]
pub fn disable_profiling() {
#[cfg(feature = "time_profiling")]
{
let _ = crate::profiling::enable_profiling(false, None);
}
#[cfg(not(feature = "time_profiling"))]
{}
}
#[internal_doc]
#[cfg(feature = "time_profiling")]
fn initialize_profile_file(path: &str) -> ProfileResult<()> {
OpenOptions::new()
.create(true)
.write(true)
.truncate(true)
.open(path)?;
Ok(())
}
#[allow(clippy::missing_const_for_fn)]
#[must_use]
pub fn is_profiling_enabled() -> bool {
#[cfg(feature = "time_profiling")]
{
#[cfg(test)]
let enabled = PROFILING_STATE.load(Ordering::SeqCst);
#[cfg(not(test))]
let enabled = PROFILING_FEATURE && PROFILING_STATE.load(Ordering::SeqCst);
enabled
}
#[cfg(not(feature = "time_profiling"))]
{
false
}
}
#[internal_doc]
#[allow(clippy::missing_const_for_fn)]
#[must_use]
pub fn is_profiling_state_enabled() -> bool {
#[cfg(feature = "time_profiling")]
{
PROFILING_STATE.load(Ordering::SeqCst)
}
#[cfg(not(feature = "time_profiling"))]
{
false
}
}
#[derive(Debug, Default, Clone, Copy, PartialEq, Eq)]
pub enum ProfileType {
Time, Memory,
#[default]
Both,
None,
}
impl Display for ProfileType {
fn fmt(&self, f: &mut Formatter<'_>) -> std::fmt::Result {
match self {
Self::Time => write!(f, "time"),
Self::Memory => write!(f, "memory"),
Self::Both => write!(f, "both"),
Self::None => write!(f, "none"),
}
}
}
impl FromStr for ProfileType {
type Err = String;
fn from_str(s: &str) -> Result<Self, Self::Err> {
let trimmed = s.trim().to_lowercase();
match trimmed.as_str() {
"time" => {
Ok(Self::Time)
}
"memory" => {
Ok(Self::Memory)
}
"both" => {
Ok(Self::Both)
}
"none" | "" => {
Ok(Self::None)
}
_ => {
let err = format!(
"Invalid profile type '{s}'. Expected 'time', 'memory', 'both', or 'none'"
);
Err(err)
}
}
}
}
#[internal_doc]
#[allow(clippy::struct_field_names, dead_code)]
#[derive(Clone, Debug)]
pub struct Profile {
start: Option<Instant>,
profile_type: ProfileType,
path: Vec<String>,
section_name: Option<String>, registered_name: String,
fn_name: String,
start_line: Option<u32>, end_line: Option<u32>, detailed_memory: bool, file_name: String, instance_id: u64, setup_duration: Duration, actual_start: Instant, #[cfg(feature = "full_profiling")]
allocation_total: Arc<AtomicUsize>, #[cfg(feature = "full_profiling")]
memory_reported: Arc<AtomicBool>, #[cfg(feature = "full_profiling")]
memory_task: Option<TaskMemoryContext>,
#[cfg(feature = "full_profiling")]
memory_guard: Option<TaskGuard>,
}
impl Profile {
#[must_use]
pub fn file_name(&self) -> &str {
&self.file_name
}
#[allow(clippy::missing_const_for_fn)]
#[must_use]
pub fn fn_name(&self) -> &str {
self.fn_name.as_str()
}
#[must_use]
pub const fn start_line(&self) -> Option<u32> {
self.start_line
}
#[must_use]
pub const fn end_line(&self) -> Option<u32> {
self.end_line
}
#[must_use]
pub const fn detailed_memory(&self) -> bool {
self.detailed_memory
}
#[must_use]
pub fn registered_name(&self) -> &str {
&self.registered_name
}
#[must_use]
pub fn section_name(&self) -> Option<String> {
self.section_name.clone()
}
#[must_use]
pub const fn instance_id(&self) -> u64 {
self.instance_id
}
#[internal_doc]
#[cfg(feature = "full_profiling")]
#[must_use]
pub fn record_allocation(&self, size: usize) -> bool {
debug_log!(
"In Profile::record_allocation for size={size} for profile {} of type {:?}, detailed_memory={}, task_id={}",
self.registered_name,
self.profile_type,
self.detailed_memory,
self.memory_task.as_ref().map_or("N/A".to_string(), |context| format!("{}", context.task_id))
);
if size == 0 {
return false;
}
self.allocation_total.fetch_add(size, Ordering::Relaxed);
debug_log!(
"Profile {} recorded allocation of {size} bytes, total now: {}",
self.registered_name,
self.allocation_total.load(Ordering::Relaxed)
);
true
}
#[allow(
clippy::inline_always,
clippy::too_many_arguments,
clippy::too_many_lines,
unused_variables
)]
#[cfg(all(feature = "time_profiling", not(feature = "full_profiling")))]
pub fn new(
section_name: Option<&str>,
_maybe_fn_name: Option<&str>,
requested_type: ProfileType,
is_async: bool,
detailed_memory: bool,
file_name: &'static str,
start_line: Option<u32>,
end_line: Option<u32>,
) -> Option<Self> {
let setup_start = Instant::now();
warn_once!(
!is_profiling_enabled(),
|| {
debug_log!("Profiling is not enabled, returning None");
},
return None
);
#[cfg(test)]
if is_test_mode_active() {
eprintln!("Test mode is active, returning None");
return None;
}
let profile_type = if matches!(requested_type, ProfileType::Memory | ProfileType::Both) {
debug_log!("Memory profiling requested but the 'full_profiling' feature is not enabled. Only time will be profiled.");
ProfileType::Time
} else {
requested_type
};
let detailed_memory = detailed_memory
&& (profile_type == ProfileType::Memory || profile_type == ProfileType::Both);
let cleaned_stack = extract_profile_callstack();
let fn_name = &cleaned_stack[0];
#[cfg(not(target_os = "windows"))]
let desc_fn_name = if is_async {
format!("async::{fn_name}")
} else {
fn_name.to_string()
};
#[cfg(target_os = "windows")]
let desc_fn_name = fn_name.to_string();
let path = extract_path(&cleaned_stack, Some(fn_name));
let stack = path.join(";");
debug_log!("Calling register_profiled_function({stack}, {desc_fn_name})");
register_profiled_function(&stack, &desc_fn_name);
let section_name = section_name.map(str::to_string);
if profile_type == ProfileType::Memory {
debug_log!("Memory profiling requested but the 'full_profiling' feature is not enabled. Only time will be profiled.");
}
debug_log!(
"NEW PROFILE: (Time) created for {}\ndesc_stack = {}",
path.join(" -> "),
build_stack(&path, section_name.as_ref(), " -> ")
);
let file_name_stem = file_stem_from_path_str(file_name);
#[cfg(feature = "full_profiling")]
let instance_id = get_next_profile_id();
#[cfg(not(feature = "full_profiling"))]
let instance_id = 0;
let setup_duration = setup_start.elapsed();
let actual_start = Instant::now();
Some(Self {
profile_type,
start: Some(actual_start),
path,
section_name,
registered_name: fn_name.to_string(),
fn_name: fn_name.to_string(),
start_line,
end_line,
detailed_memory,
file_name: file_name_stem,
instance_id,
setup_duration,
actual_start,
})
}
#[allow(
clippy::inline_always,
clippy::too_many_arguments,
clippy::too_many_lines,
unused_variables
)]
#[cfg(feature = "full_profiling")]
pub fn new(
section_name: Option<&str>,
_maybe_fn_name: Option<&str>,
requested_type: ProfileType,
is_async: bool,
detailed_memory: bool,
file_name: &'static str,
start_line: Option<u32>,
end_line: Option<u32>,
) -> Option<Self> {
let setup_start = Instant::now();
warn_once!(
!is_profiling_enabled(),
|| {
debug_log!("Profiling is not enabled, returning None");
},
return None
);
#[cfg(test)]
if is_test_mode_active() {
eprintln!("Test mode is active, returning None");
return None;
}
safe_alloc! {
let start = Instant::now();
let profile_type = requested_type;
let file_name_stem = file_stem_from_path_str(file_name);
let start_pattern = "Profile::new";
let cleaned_stack = extract_profile_callstack();
if cleaned_stack.is_empty() {
debug_log!("Empty cleaned stack found");
return None;
}
let fn_name = &cleaned_stack[0];
#[cfg(not(target_os = "windows"))]
let desc_fn_name = if section_name.is_some() && is_profiled_function(fn_name) {
safe_alloc!(get_reg_desc_name(fn_name).unwrap_or_else(|| fn_name.to_string()))
} else if is_async {
safe_alloc!(format!("async::{fn_name}"))
} else {
safe_alloc!(fn_name.to_string())
};
#[cfg(target_os = "windows")]
let desc_fn_name = safe_alloc!(fn_name.to_string());
let path = extract_path(&cleaned_stack, Some(fn_name));
let stack = path.join(";");
register_profiled_function(&stack, &desc_fn_name);
let section_name = section_name.map(str::to_string);
let instance_id = get_next_profile_id();
if profile_type == ProfileType::Time {
debug_log!(
"NEW PROFILE: (Time) created for {}\ndesc_stack = {}",
path.join(" -> "),
build_stack(&path, section_name.as_ref(), " -> ")
);
let setup_duration = setup_start.elapsed();
let actual_start = Instant::now();
let mut profile = Self {
profile_type,
start: None,
path,
section_name,
registered_name: stack,
fn_name: fn_name.to_string(),
start_line,
end_line,
detailed_memory,
file_name: file_name_stem,
instance_id,
setup_duration,
actual_start,
allocation_total: Arc::new(AtomicUsize::new(0)),
memory_reported: Arc::new(AtomicBool::new(false)),
memory_task: None,
memory_guard: None,
};
register_profile(&profile);
profile.start = Some(Instant::now());
return Some(profile);
}
let memory_task = create_memory_task();
let task_id = memory_task.id();
let mut registry = TASK_PATH_REGISTRY.lock();
registry.insert(task_id, path.clone());
let reg_len = registry.len();
drop(registry);
activate_task(task_id);
debug_log!(
"NEW PROFILE: Task {task_id} created for {}\ndesc_stack = {}",
path.join(" -> "),
build_stack(&path, section_name.as_ref(), " -> ")
);
let memory_guard = TaskGuard::new(task_id);
let mut profile = {
debug_log!(
"Creating profile for {} in file {} with memory profiling enabled={}",
fn_name,
file_name_stem,
matches!(profile_type, ProfileType::Memory | ProfileType::Both)
);
let setup_duration = setup_start.elapsed();
let actual_start = Instant::now();
Self {
profile_type,
start: None,
path,
section_name,
registered_name: stack,
fn_name: fn_name.to_string(),
start_line,
end_line,
detailed_memory,
#[cfg(feature = "debug_logging")]
file_name: file_name_stem.clone(),
#[cfg(not(feature = "debug_logging"))]
file_name: file_name_stem,
instance_id,
setup_duration,
actual_start,
allocation_total: Arc::new(AtomicUsize::new(0)),
memory_reported: Arc::new(AtomicBool::new(false)),
memory_task: Some(memory_task),
memory_guard: Some(memory_guard),
}
};
debug_log!(
"About to register profile in module {} for fn {} with line range {:?}..None",
file_name_stem,
fn_name,
start_line
);
#[cfg(feature = "full_profiling")]
register_profile(&profile);
debug_log!(
"Successfully registered profile in module {}",
&profile.file_name
);
profile.start = Some(profile.actual_start);
Some(profile)
}
}
#[must_use]
pub const fn path(&self) -> &Vec<String> {
&self.path
}
#[cfg(feature = "time_profiling")]
pub fn write_profile_event(
path: &str,
file: &Mutex<Option<BufWriter<File>>>,
entry: &str,
) -> ProfileResult<()> {
let mut guard = file.lock();
if guard.is_none() {
*guard = Some(BufWriter::new(
OpenOptions::new().create(true).append(true).open(path)?,
));
}
if let Some(writer) = guard.as_mut() {
writeln!(writer, "{entry}")?;
writer.flush()?;
}
drop(guard);
Ok(())
}
#[cfg(feature = "time_profiling")]
fn write_profraw_event(
&self,
payload_duration: Duration,
overhead_duration: Duration,
) -> ProfileResult<()> {
let payload_micros = payload_duration.as_micros();
let overhead_micros = overhead_duration.as_micros();
if payload_micros == 0 {
debug_log!(
"DEBUG: Not writing profraw event for stack: {:?} due to zero payload duration",
self.path
);
return Ok(());
}
let path = &self.path;
if path.is_empty() {
debug_log!("DEBUG: Stack is empty for {:?}", self.section_name);
return Err(ProfileError::General("Stack is empty".into()));
}
let stack = self.build_stack(path);
let entry = format!("{stack} {payload_micros} {overhead_micros}");
let paths = ProfilePaths::get();
let profraw_path = &paths.profraw;
Self::write_profile_event(profraw_path, ProfrawProfileFile::get(), &entry)
}
#[cfg(feature = "full_profiling")]
fn write_memory_event(&self, delta: usize, op: char) -> ProfileResult<()> {
if delta == 0 {
debug_log!(
"DEBUG: Not writing memory event for stack: {:?} due to zero delta",
self.path
);
return Ok(());
}
let path = &self.path;
if path.is_empty() {
return Err(ProfileError::General("Stack is empty".into()));
}
let stack = self.build_stack(path);
let entry = format!("{stack} {}{delta}", if op == '-' { "-" } else { "" });
debug_log!(
"DEBUG: task_id: {} section_name: {:?} write_memory_event: {entry}",
self.memory_task.as_ref().unwrap().id(),
self.section_name
);
let memory_path = get_memory_path()?;
Self::write_profile_event(memory_path, MemoryProfileFile::get(), &entry)
}
#[internal_doc]
#[cfg(feature = "time_profiling")]
#[must_use]
pub fn build_stack(&self, path: &[String]) -> std::string::String {
build_stack(path, self.section_name.as_ref(), ";")
}
#[cfg(feature = "full_profiling")]
#[allow(clippy::branches_sharing_code)]
fn record_memory_change(&self, delta: usize) {
if delta == 0 {
return;
}
debug_log!(
"Recording memory change: delta={}, profile={}, detailed_memory={}",
delta,
self.registered_name(),
self.detailed_memory()
);
let result = self.write_memory_event(delta, '+');
if let Err(ref e) = result {
debug_log!("Error writing memory event: {:?}", e);
} else {
debug_log!("Successfully wrote memory event for delta={}", delta);
}
}
#[must_use]
pub const fn get_profile_type(&self) -> ProfileType {
self.profile_type
}
#[must_use]
pub const fn is_detailed_memory(&self) -> bool {
self.detailed_memory
}
}
#[internal_doc]
#[cfg(feature = "time_profiling")]
#[must_use]
pub fn build_stack(
path: &[String],
maybe_section_name: Option<&String>,
sep: &str,
) -> std::string::String {
safe_alloc! {
let mut vanilla_stack = String::new();
path.iter()
.map(|fn_name_str| {
let stack_str = if vanilla_stack.is_empty() {
fn_name_str.to_string()
} else {
format!("{vanilla_stack};{fn_name_str}")
};
vanilla_stack.clone_from(&stack_str);
(stack_str, fn_name_str)
})
.map(|(stack_str, fn_name_str)| {
get_reg_desc_name(&stack_str).unwrap_or_else(|| fn_name_str.to_string())
})
.chain(maybe_section_name.cloned())
.collect::<Vec<String>>()
.join(sep)
}
}
#[internal_doc]
#[cfg(feature = "time_profiling")]
#[must_use]
pub fn extract_path(cleaned_stack: &[String], maybe_append: Option<&String>) -> Vec<String> {
#[cfg(all(not(feature = "full_profiling"), feature = "time_profiling"))]
{
let dup = maybe_append
.and_then(|append| cleaned_stack.first().map(|first| first == append))
== Some(true);
let start = usize::from(dup);
cleaned_stack[start..]
.iter()
.rev()
.fold(vec![], |stack: Vec<String>, fn_name_str| {
let new_vec: Vec<String> = stack.iter().chain(Some(fn_name_str)).cloned().collect();
let stack_str = new_vec.join(";");
if is_profiled_function(&stack_str) {
new_vec
} else {
stack
}
})
.iter()
.chain(maybe_append)
.cloned()
.collect()
}
#[cfg(feature = "full_profiling")]
safe_alloc! {
let dup = maybe_append.and_then(|append| cleaned_stack.first().map(|first| first == append))
== Some(true);
let start = usize::from(dup);
let mut stack = Vec::new();
let mut stack_str = String::new();
for frame in cleaned_stack[start..].iter().rev() {
let mut temp_stack_str = stack_str.clone();
if !temp_stack_str.is_empty() {
temp_stack_str.push(';');
}
temp_stack_str.push_str(frame);
if is_profiled_function(&temp_stack_str) {
stack.push(frame.to_string());
if !stack_str.is_empty() {
stack_str.push(';');
}
stack_str.push_str(frame);
debug_log!("frame={frame}, stack_str={stack_str}");
}
}
if let Some(append_name) = maybe_append {
stack.push(append_name.to_string());
}
stack
}
}
#[internal_doc]
#[cfg(feature = "time_profiling")]
#[must_use]
pub fn filter_scaffolding(name: &str) -> bool {
!name.starts_with("tokio::") && !SCAFFOLDING_PATTERNS.iter().any(|s| name.contains(s))
}
#[internal_doc]
#[allow(clippy::too_many_lines)]
#[cfg(feature = "time_profiling")]
#[must_use]
pub fn extract_profile_callstack() -> Vec<String> {
const MAX_STACK_DEPTH_CAP: usize = 1000;
const INITIAL_STACK_DEPTH: usize = 20;
const START_PATTERN: &str = "Profile::new";
#[derive(Debug)]
struct Site {
filename: Option<PathBuf>,
name: String,
}
let end_point = safe_alloc!(get_base_location().unwrap_or("__rust_begin_short_backtrace"));
let mut already_seen = safe_alloc!(HashSet::new());
let mut recursion_detected = false;
safe_alloc! {
let mut callstack: Vec<String> = Vec::with_capacity(INITIAL_STACK_DEPTH);
let mut start = false;
let mut fin = false;
let mut is_current_fn = false;
let mut maybe_site: Option<Site> = None;
trace(|frame| {
let mut suppress = false;
resolve_frame(frame, |symbol| {
'process_symbol: {
let Some(name) = symbol.name() else {
suppress = true;
break 'process_symbol;
};
let name = name.to_string();
if name.contains("tokio") {
suppress = true;
break 'process_symbol;
}
if !start {
if name.contains(START_PATTERN) && !name.contains("{{closure}}") {
start = true;
is_current_fn = true;
}
suppress = true;
break 'process_symbol;
}
if name.contains(end_point) {
fin = true;
suppress = true;
break 'process_symbol;
}
let filename = symbol.filename().map(Path::to_path_buf);
let lineno = symbol.lineno();
if is_current_fn {
is_current_fn = false;
maybe_site = Some(Site{
filename,
name: name.clone(),
});
} else if let Some(site) = &maybe_site {
if name == site.name && filename == site.filename {
recursion_detected = true;
eprintln!("Recursion detected for filename={filename:#?}, name={name}, lineno={lineno:?}");
suppress = true;
break 'process_symbol;
}
}
for &s in SCAFFOLDING_PATTERNS {
if name.contains(s) {
suppress = true;
break 'process_symbol;
}
}
let mut name = strip_hex_suffix_slice(&name);
let name = clean_function_name(&mut name);
if already_seen.contains(&name) {
suppress = true;
break 'process_symbol;
}
already_seen.insert(name.clone());
if suppress { break 'process_symbol; }
if callstack.len() >= callstack.capacity() {
if callstack.capacity() >= MAX_STACK_DEPTH_CAP {
debug_log!(
"Stack depth capped at {}, stopping at {} frames",
MAX_STACK_DEPTH_CAP,
callstack.len()
);
fin = true;
break 'process_symbol;
}
safe_alloc!{
let new_capacity = (callstack.capacity() * 2).min(MAX_STACK_DEPTH_CAP);
callstack.reserve(new_capacity - callstack.len());
debug_log!(
"Resized callstack capacity from {} to {}",
callstack.capacity() / 2,
new_capacity
);
}
}
callstack.push(name);
}
});
!fin && !recursion_detected
});
assert!(!recursion_detected,
r"THAG_PROFILER ERROR: Recursive profiling detected for above location.
Profiling recursive functions may cause exponential overhead and is not supported.
Please remove #[profiled] from recursive functions and profile only the calling function instead."
);
callstack
}
}
#[internal_doc]
#[cfg(feature = "full_profiling")]
#[must_use]
#[fn_name]
pub fn extract_detailed_alloc_callstack(start_pattern: &Regex) -> Vec<String> {
let mut already_seen = HashSet::new();
let end_point = "__rust_begin_short_backtrace";
let maybe_callstack: Option<Vec<String>> = safe_alloc! {
let capacity = 100;
let mut callstack: Vec<String> = Vec::with_capacity(capacity); let mut found_recursion = false;
let mut start = false;
let mut fin = false;
let mut i = 0;
trace(|frame| {
let mut suppress = false;
resolve_frame(frame, |symbol| {
'process_symbol: {
let Some(name) = symbol.name() else {
suppress = true;
break 'process_symbol;
};
let name = name.to_string();
if !start {
if start_pattern.is_match(&name) {
start = true;
}
suppress = true;
break 'process_symbol;
}
if name.contains(end_point) {
fin = true;
suppress = true;
break 'process_symbol;
}
let mut name = strip_hex_suffix_slice(&name);
let name = clean_function_name(&mut name);
if already_seen.contains(&name) {
suppress = true;
break 'process_symbol;
}
already_seen.insert(name.clone());
if suppress { break 'process_symbol; }
if i > 0 && name.contains(fn_name) {
found_recursion = true;
break 'process_symbol;
}
callstack.push(name);
i += 1;
if i >= capacity {
safe_alloc! {
println!("frames={callstack:#?}");
};
panic!("Max limit of {capacity} frames exceeded");
}
}
});
!found_recursion && !fin
});
if found_recursion {
None } else {
Some(callstack)
}
};
let Some(callstack) = maybe_callstack else {
return vec![];
};
callstack
.iter()
.rev()
.cloned()
.collect()
}
static GLOBAL_CALL_STACK_ENTRIES: std::sync::LazyLock<Mutex<BTreeSet<String>>> =
std::sync::LazyLock::new(|| Mutex::new(BTreeSet::new()));
pub fn print_all_call_stack_entries() {
let parts = { GLOBAL_CALL_STACK_ENTRIES.lock().clone() };
debug_log!("All entries in the global set (sorted):");
if parts.is_empty() {
debug_log!(" (empty set)");
} else {
for part in &parts {
debug_log!(" {part}");
}
}
debug_log!("Total entries: {}", parts.len());
}
#[allow(dead_code)]
fn get_fn_desc_name(fn_name_str: &String) -> String {
extract_fn_only(fn_name_str).unwrap_or_else(|| fn_name_str.to_string())
}
#[cfg(all(not(feature = "full_profiling"), feature = "time_profiling"))]
impl Drop for Profile {
fn drop(&mut self) {
let drop_start = Instant::now();
if let Some(start) = self.start.take() {
match self.profile_type {
ProfileType::Time | ProfileType::Both => {
let payload_duration = start.elapsed();
let drop_duration = drop_start.elapsed();
let total_overhead = self.setup_duration + drop_duration;
let _ = self.write_profraw_event(payload_duration, total_overhead);
}
ProfileType::Memory | ProfileType::None => todo!(),
}
}
debug_log!(
"Time to drop profile: {}ms",
drop_start.elapsed().as_millis()
);
flush_debug_log();
}
}
#[cfg(feature = "full_profiling")]
impl Drop for Profile {
#[allow(clippy::branches_sharing_code)]
fn drop(&mut self) {
safe_alloc! {
#[cfg(feature = "full_profiling")]
let instance_id = self.instance_id();
let drop_start = Instant::now();
if let Some(start) = self.start.take() {
match self.profile_type {
ProfileType::Time | ProfileType::Both => {
if matches!(
get_global_profile_type(),
ProfileType::Time | ProfileType::Both
) {
let payload_duration = start.elapsed();
let drop_duration = drop_start.elapsed();
let total_overhead = self.setup_duration + drop_duration;
let _ = self.write_profraw_event(payload_duration, total_overhead);
}
}
ProfileType::Memory | ProfileType::None => (),
}
}
debug_log!(
"Time to write event: {}ms",
drop_start.elapsed().as_millis()
);
if matches!(self.profile_type, ProfileType::Memory | ProfileType::Both) {
if self
.memory_reported
.compare_exchange(false, true, Ordering::SeqCst, Ordering::SeqCst)
.is_ok()
{
let total_allocated = self.allocation_total.load(Ordering::Relaxed);
if total_allocated > 0 {
debug_log!(
"Writing memory allocation of {total_allocated} bytes for profile {}",
self.registered_name
);
self.record_memory_change(total_allocated);
} else {
debug_log!(
"0-byte memory allocation not recorded for profile {}",
self.registered_name
);
}
} else {
debug_log!(
"Skipping memory write for profile {} - already reported",
self.registered_name
);
}
}
debug_log!(
"Time to drop profile: {}ms",
drop_start.elapsed().as_millis()
);
#[cfg(feature = "full_profiling")]
{
debug_log!("Requesting deregistration of profile instance {instance_id}");
deregister_profile(self);
}
};
}
}
#[internal_doc]
#[cfg(feature = "time_profiling")]
#[allow(clippy::branches_sharing_code, unused_assignments)]
pub fn convert_to_exclusive_time(input_path: &str, output_path: &str) -> ProfileResult<()> {
use std::string::ToString;
debug_log!("Converting inclusive time profile to exclusive time");
let file = File::open(input_path)
.map_err(|e| ProfileError::General(format!("Failed to open input file: {e}")))?;
let reader = BufReader::new(file);
let mut stack_lines: Vec<(String, u64)> = Vec::new();
let mut input_lines = 0;
for (line_count, line) in reader.lines().enumerate() {
input_lines = line_count;
let line = line.map_err(|e| ProfileError::General(format!("Failed to read line: {e}")))?;
let parts: Vec<&str> = line.rsplitn(2, ' ').collect();
if parts.len() != 2 {
debug_log!("Warning: Invalid line format at line {line_count}: {line}");
continue;
}
let stack_str = parts[1].trim();
let time = match parts[0].parse::<u64>() {
Ok(t) => t,
Err(e) => {
debug_log!("Warning: Invalid time value at line {line_count}: {e}");
continue;
}
};
stack_lines.push((stack_str.to_string(), time));
}
let len = &stack_lines.len();
let parsed_stacks: Vec<(Vec<String>, u64, String)> = stack_lines
.into_iter()
.map(|(stack, time)| {
let parts: Vec<String> = stack.split(';').map(ToString::to_string).collect();
(parts, time, stack)
})
.collect();
let mut exclusive_times: Vec<(String, u64)> = parsed_stacks
.iter()
.map(|(_, time, stack)| (stack.clone(), *time))
.collect();
for i in (0..parsed_stacks.len()).rev() {
let (ref current_parts, _, _) = &parsed_stacks[i];
for stack in parsed_stacks.iter().take(i) {
let (ref child_parts, child_time, _) = &stack;
if child_parts.len() == current_parts.len() + 1 {
let is_parent = child_parts[..current_parts.len()]
.iter()
.zip(current_parts.iter())
.all(|(child, parent)| child == parent);
if is_parent {
exclusive_times[i].1 = exclusive_times[i].1.saturating_sub(*child_time);
}
}
}
}
let output_file = OpenOptions::new()
.write(true)
.create(true)
.truncate(true)
.open(output_path)
.map_err(|e| ProfileError::General(format!("Failed to create output file: {e}")))?;
let mut writer = BufWriter::new(output_file);
for (stack, exclusive) in &exclusive_times {
writeln!(writer, "{stack} {exclusive}")
.map_err(|e| ProfileError::General(format!("Failed to write stack line: {e}")))?;
}
writer
.flush()
.map_err(|e| ProfileError::General(format!("Failed to flush writer: {e}")))?;
debug_log!("Successfully processed {input_lines} lines");
debug_log!("Found {len} stacks");
let total_exclusive: u64 = exclusive_times.iter().map(|(_, time)| *time).sum();
debug_log!("Total exclusive time: {total_exclusive} µs");
debug_log!("Successfully converted time profile from inclusive to exclusive time");
Ok(())
}
#[internal_doc]
#[cfg(feature = "time_profiling")]
pub fn process_time_profile() -> ProfileResult<()> {
let paths = ProfilePaths::get();
let profraw_path = &paths.profraw;
let inclusive_path = &paths.inclusive_time;
let exclusive_path = &paths.time;
if profraw_path.is_empty() {
if !inclusive_path.is_empty() {
let metadata = std::fs::metadata(inclusive_path).map_err(|e| {
ProfileError::General(format!("Failed to check inclusive time file: {e}"))
})?;
if metadata.len() > 0 {
debug_log!("Converting inclusive time profile to exclusive time");
convert_to_exclusive_time(inclusive_path, exclusive_path)?;
}
}
} else {
let metadata = std::fs::metadata(profraw_path)
.map_err(|e| ProfileError::General(format!("Failed to check .profraw file: {e}")))?;
if metadata.len() > 0 {
debug_log!("Converting .profraw to clean inclusive time profile");
process_profraw_to_folded(profraw_path, inclusive_path)?;
debug_log!("Converting clean inclusive time profile to exclusive time");
convert_to_exclusive_time(inclusive_path, exclusive_path)?;
}
}
Ok(())
}
#[internal_doc]
#[cfg(feature = "full_profiling")]
#[allow(dead_code)]
fn backtrace_contains_any(backtrace: &str, patterns: &[&str]) -> bool {
let lines = backtrace.lines();
for line in lines {
for &pattern in patterns {
if line.contains(pattern) {
return true;
}
}
}
false
}
#[internal_doc]
pub fn register_profiled_function(name: &str, desc_name: &str) {
#[cfg(all(debug_assertions, not(test)))]
assert!(
name != "new",
"Logic error: `new` is not an accepted function name on its own. It must be qualified with the type name: `<Type>::new`. desc_name={desc_name}"
);
let name = safe_alloc!(name.to_string());
let desc_name = safe_alloc!(desc_name.to_string());
{
if let Some(mut lock) = PROFILED_FUNCTIONS.try_write() {
safe_alloc!(lock.insert(name, desc_name));
} else {
safe_alloc!(debug_log!(
"register_profiled_function failed to acquire write lock on PROFILED_FUNCTIONS"
););
}
}
}
pub fn is_profiled_function(name: &str) -> bool {
let contains_key = PROFILED_FUNCTIONS.try_read().map_or_else(
|| {
debug_log!("is_profiled_function failed to acquire read lock on PROFILED_FUNCTIONS");
false
},
|lock| lock.contains_key(name),
);
contains_key
}
pub fn get_reg_desc_name(name: &str) -> Option<String> {
safe_alloc! {
let maybe_reg_desc_name = PROFILED_FUNCTIONS.try_read().map_or_else(
|| {
debug_log!("get_reg_desc_name failed to acquire read lock on PROFILED_FUNCTIONS");
None
},
|lock| lock.get(name).cloned(),
);
maybe_reg_desc_name
}
}
fn extract_fn_only(qualified_name: &str) -> Option<String> {
qualified_name.rfind("::").map_or_else(
|| Some(qualified_name.to_string()),
|pos| Some(qualified_name[(pos + 2)..].to_string()),
)
}
#[cfg(feature = "time_profiling")]
const SCAFFOLDING_PATTERNS: &[&str] = &[
"::poll::",
"::poll_next_unpin",
"<F as core::future::future::Future>::poll",
"FuturesOrdered<Fut>",
"FuturesUnordered<Fut>",
"ProfiledFuture",
"ProfileSection",
"__rust_alloc",
"__rust_realloc",
"__rust_try",
"alloc::",
"core::",
"core::ops::function::FnOnce::call_once",
"hashbrown",
"mem_tracking::with_sys_alloc",
"mio::",
"std::panic::catch_unwind",
"std::panicking",
"std::rt::lang_start",
"std::sync::poison::",
"std::sys::backtrace::__rust_begin_short_backtrace",
"std::sys::sync::",
"std::sys::thread_local",
"std::thread",
"mem_tracking::MultiAllocator::with",
];
#[internal_doc]
pub fn clean_function_name(name: &mut str) -> String {
let trimmed = if let Some(pos) = name.find("::{{closure}}") {
&name[..pos]
} else if let Some(pos) = name.rfind("::h") {
let hex = &name[pos + 3..];
if hex.chars().all(|c| c.is_ascii_hexdigit()) {
&name[..pos]
} else {
name
}
} else {
name
};
let trimmed = trimmed.trim_end_matches("::");
let mut result = String::with_capacity(trimmed.len());
let mut chars = trimmed.chars().peekable();
while let Some(c) = chars.next() {
if c == ':' && chars.peek() == Some(&':') {
while chars.peek() == Some(&':') {
chars.next();
}
result.push_str("::");
} else {
result.push(c);
}
}
result
}
#[derive(Debug)]
pub enum MemoryError {
StatsUnavailable,
DeltaCalculationFailed,
}
#[derive(Default)]
pub struct ProfileStats {
pub calls: HashMap<String, u64>,
pub total_time: HashMap<String, u128>,
count: u64,
duration_total: std::time::Duration,
min_time: Option<std::time::Duration>,
max_time: Option<std::time::Duration>,
}
impl ProfileStats {
pub fn record(&mut self, func_name: &str, duration: std::time::Duration) {
*self.calls.entry(func_name.to_string()).or_default() += 1;
*self.total_time.entry(func_name.to_string()).or_default() += duration.as_micros();
}
#[must_use]
pub fn average(&self) -> Option<std::time::Duration> {
if self.count > 0 {
let count = u32::try_from(self.count).unwrap_or(u32::MAX);
Some(self.duration_total / count)
} else {
None
}
}
#[must_use]
pub const fn count(&self) -> u64 {
self.count
}
#[must_use]
pub const fn total_duration(&self) -> std::time::Duration {
self.duration_total
}
#[must_use]
pub const fn min_time(&self) -> Option<std::time::Duration> {
self.min_time
}
#[must_use]
pub const fn max_time(&self) -> Option<std::time::Duration> {
self.max_time
}
}
#[cfg(any(test, debug_assertions))]
pub fn dump_profiled_functions() -> Vec<(String, String)> {
let hash_map = { PROFILED_FUNCTIONS.read().clone() };
hash_map
.iter()
.map(|(k, v)| (k.clone(), v.clone()))
.collect()
}
#[allow(dead_code)]
static TEST_MODE_ACTIVE: std::sync::atomic::AtomicBool = std::sync::atomic::AtomicBool::new(false);
#[cfg(test)]
#[inline]
pub fn is_test_mode_active() -> bool {
TEST_MODE_ACTIVE.load(Ordering::SeqCst)
}
#[cfg(feature = "time_profiling")]
pub fn force_set_profiling_state(enabled: bool) {
PROFILING_STATE.store(enabled, Ordering::SeqCst);
}
#[cfg(test)]
#[cfg(feature = "time_profiling")]
pub fn force_enable_profiling_time_for_tests() {
use std::sync::atomic::Ordering;
TEST_MODE_ACTIVE.store(true, Ordering::SeqCst);
PROFILING_STATE.store(true, Ordering::SeqCst);
set_global_profile_type(ProfileType::Time);
let _ = initialize_profile_files(ProfileType::Time);
}
#[cfg(feature = "full_profiling")]
pub fn force_enable_profiling_memory_for_tests() {
use std::sync::atomic::Ordering;
TEST_MODE_ACTIVE.store(true, Ordering::SeqCst);
PROFILING_STATE.store(true, Ordering::SeqCst);
set_global_profile_type(ProfileType::Memory);
let _ = initialize_profile_files(ProfileType::Memory);
}
#[cfg(all(test, feature = "full_profiling"))]
pub fn force_enable_profiling_both_for_tests() {
use std::sync::atomic::Ordering;
TEST_MODE_ACTIVE.store(true, Ordering::SeqCst);
PROFILING_STATE.store(true, Ordering::SeqCst);
set_global_profile_type(ProfileType::Both);
let _ = initialize_profile_files(ProfileType::Both);
}
#[cfg(test)]
pub fn safely_cleanup_profiling_after_test() {
use std::sync::atomic::Ordering;
disable_profiling();
TEST_MODE_ACTIVE.store(false, Ordering::SeqCst);
}
#[internal_doc]
#[must_use]
pub fn strip_hex_suffix_slice(name: &str) -> String {
name.rfind("::h").map_or_else(
|| name.to_string(),
|hash_pos| {
if name[hash_pos + 3..].chars().all(|c| c.is_ascii_hexdigit()) {
name[..hash_pos].to_string()
} else {
name.to_string()
}
},
)
}
pub fn extract_filename_timestamp(filename: &str) -> DateTime<Local> {
let re = re!(r"^([\w/\\]+)\-(\d{8}\-\d{6})");
re.captures(filename)
.map_or_else(DateTime::default, |captures| {
let _script_stem = captures.get(1).unwrap().as_str();
let datetime_str = captures.get(2).unwrap().as_str();
NaiveDateTime::parse_from_str(datetime_str, "%Y%m%d-%H%M%S").map_or_else(
|_| {
println!("Failed to parse datetime");
DateTime::default()
},
|naive_dt| Local.from_local_datetime(&naive_dt).single().unwrap(),
)
})
}
#[cfg(feature = "time_profiling")]
#[derive(Debug, Clone)]
struct ProfrawEntry {
stack: String,
payload_micros: u64,
overhead_micros: u64,
}
#[cfg(feature = "time_profiling")]
fn parse_profraw_file(profraw_path: &str) -> ProfileResult<Vec<ProfrawEntry>> {
debug_log!("Parsing .profraw file: {}", profraw_path);
let file = File::open(profraw_path)
.map_err(|e| ProfileError::General(format!("Failed to open .profraw file: {e}")))?;
let reader = BufReader::new(file);
let mut entries = Vec::new();
for (line_number, line) in reader.lines().enumerate() {
let line = line.map_err(|e| {
ProfileError::General(format!("Failed to read line {}: {e}", line_number + 1))
})?;
if line.trim().is_empty() {
continue;
}
let parts: Vec<&str> = line.rsplitn(3, ' ').collect();
if parts.len() != 3 {
debug_log!(
"Warning: Invalid line format at line {}: {}",
line_number + 1,
line
);
continue;
}
let stack = parts[2].trim().to_string();
let payload_micros = match parts[1].parse::<u64>() {
Ok(p) => p,
Err(e) => {
debug_log!(
"Warning: Invalid payload value at line {}: {}",
line_number + 1,
e
);
continue;
}
};
let overhead_micros = match parts[0].parse::<u64>() {
Ok(o) => o,
Err(e) => {
debug_log!(
"Warning: Invalid overhead value at line {}: {}",
line_number + 1,
e
);
continue;
}
};
entries.push(ProfrawEntry {
stack,
payload_micros,
overhead_micros,
});
}
debug_log!("Parsed {} entries from .profraw file", entries.len());
Ok(entries)
}
#[cfg(feature = "time_profiling")]
fn subtract_child_overhead(entries: &[ProfrawEntry]) -> Vec<(String, u64)> {
debug_log!("Subtracting child overhead from parent payload");
let mut result = Vec::new();
let mut stack_totals = HashMap::new();
let mut stack_overhead = HashMap::new();
for entry in entries {
*stack_overhead.entry(entry.stack.clone()).or_insert(0) += entry.overhead_micros;
}
for entry in entries {
let stack_parts: Vec<&str> = entry.stack.split(';').collect();
let mut child_overhead = 0u64;
for other_entry in entries {
let other_parts: Vec<&str> = other_entry.stack.split(';').collect();
if other_parts.len() > stack_parts.len() {
let other_prefix = &other_parts[0..stack_parts.len()];
if other_prefix == stack_parts {
child_overhead += other_entry.overhead_micros;
}
}
}
let clean_payload = entry.payload_micros.saturating_sub(child_overhead);
*stack_totals.entry(entry.stack.clone()).or_insert(0) += clean_payload;
debug_log!(
"Stack: {} | Original payload: {}μs | Child overhead: {}μs | Clean payload: {}μs",
entry.stack,
entry.payload_micros,
child_overhead,
clean_payload
);
}
let mut processed_stacks = HashSet::new();
for entry in entries {
if !processed_stacks.contains(&entry.stack) {
let total_time = stack_totals[&entry.stack];
if total_time > 0 {
result.push((entry.stack.clone(), total_time));
}
processed_stacks.insert(entry.stack.clone());
}
}
debug_log!("Generated {} clean inclusive times", result.len());
result
}
#[cfg(feature = "time_profiling")]
pub fn process_profraw_to_folded(profraw_path: &str, output_path: &str) -> ProfileResult<()> {
debug_log!(
"Converting .profraw to clean .folded: {} -> {}",
profraw_path,
output_path
);
let entries = parse_profraw_file(profraw_path)?;
if entries.is_empty() {
debug_log!("No entries found in .profraw file, creating empty .folded file");
File::create(output_path)
.map_err(|e| ProfileError::General(format!("Failed to create output file: {e}")))?;
return Ok(());
}
let clean_times = subtract_child_overhead(&entries);
let mut output_file = File::create(output_path)
.map_err(|e| ProfileError::General(format!("Failed to create output file: {e}")))?;
for (stack, time_micros) in clean_times {
writeln!(output_file, "{} {}", stack, time_micros)
.map_err(|e| ProfileError::General(format!("Failed to write to output file: {e}")))?;
}
debug_log!("Successfully converted .profraw to clean .folded file");
Ok(())
}
#[cfg(feature = "time_profiling")]
pub fn process_all_profraw_files() -> ProfileResult<()> {
debug_log!("Processing all .profraw files in current directory");
let current_dir = std::env::current_dir()
.map_err(|e| ProfileError::General(format!("Failed to get current directory: {e}")))?;
let mut _processed_count = 0;
for entry in std::fs::read_dir(¤t_dir)
.map_err(|e| ProfileError::General(format!("Failed to read directory: {e}")))?
{
let entry = entry
.map_err(|e| ProfileError::General(format!("Failed to read directory entry: {e}")))?;
let path = entry.path();
if let Some(extension) = path.extension() {
if extension == "profraw" {
let profraw_path = path.to_string_lossy();
let folded_path = profraw_path.replace(".profraw", "-inclusive.folded");
debug_log!("Processing: {} -> {}", profraw_path, folded_path);
match process_profraw_to_folded(&profraw_path, &folded_path) {
Ok(()) => {
_processed_count += 1;
debug_log!("Successfully processed: {}", profraw_path);
}
Err(e) => {
debug_log!("Failed to process {}: {}", profraw_path, e);
}
}
}
}
}
debug_log!("Processed {} .profraw files", _processed_count);
Ok(())
}
#[cfg(test)]
#[cfg(feature = "time_profiling")]
pub(crate) mod test_utils {
#[cfg(feature = "full_profiling")]
use crate::ProfileType;
#[cfg(feature = "full_profiling")]
pub fn initialize_profiling_for_test(profile_type: ProfileType) -> crate::ProfileResult<()> {
use crate::profiling::{enable_profiling, TEST_MODE_ACTIVE};
use std::sync::atomic::Ordering;
TEST_MODE_ACTIVE.store(true, Ordering::SeqCst);
enable_profiling(true, Some(profile_type))
}
}
#[cfg(test)]
mod tests_internal {
use super::*;
use regex::Regex;
use serial_test::serial;
use std::time::Duration;
#[test]
#[serial]
fn test_profiling_profile_type_from_str() {
assert_eq!(ProfileType::from_str("time"), Ok(ProfileType::Time));
assert_eq!(ProfileType::from_str("memory"), Ok(ProfileType::Memory));
assert_eq!(ProfileType::from_str("both"), Ok(ProfileType::Both));
assert_eq!(ProfileType::from_str("none"), Ok(ProfileType::None));
assert_eq!(ProfileType::from_str(""), Ok(ProfileType::None));
assert_eq!(
ProfileType::from_str("invalid"),
Err(
"Invalid profile type 'invalid'. Expected 'time', 'memory', 'both', or 'none'"
.to_string()
)
);
}
#[test]
#[serial]
fn test_profiling_function_registry() {
register_profiled_function("test_func", "test_desc");
assert!(is_profiled_function("test_func"));
assert_eq!(
get_reg_desc_name("test_func"),
Some("test_desc".to_string())
);
assert!(!is_profiled_function("nonexistent"));
assert_eq!(get_reg_desc_name("nonexistent"), None);
}
#[test]
fn test_profiling_profile_stats() {
let mut stats = ProfileStats::default();
stats.record("func1", Duration::from_micros(100));
stats.record("func1", Duration::from_micros(200));
stats.record("func2", Duration::from_micros(150));
assert_eq!(*stats.calls.get("func1").unwrap(), 2);
assert_eq!(*stats.calls.get("func2").unwrap(), 1);
assert_eq!(*stats.total_time.get("func1").unwrap(), 300);
assert_eq!(*stats.total_time.get("func2").unwrap(), 150);
}
#[test]
fn test_profiling_clean_function_name() {
let mut name = "module::func::h1234abcd".to_string();
assert_eq!(clean_function_name(&mut name), "module::func");
let mut name = "module::func::{{closure}}".to_string();
assert_eq!(clean_function_name(&mut name), "module::func");
let mut name = "module::func::{{closure}}::h1234abcd".to_string();
assert_eq!(clean_function_name(&mut name), "module::func");
let mut name = "module::::func".to_string();
assert_eq!(clean_function_name(&mut name), "module::func");
}
#[test]
fn test_profiling_extract_fn_only() {
let name = "module::submodule::function";
assert_eq!(extract_fn_only(name), Some("function".to_string()));
let name = "function";
assert_eq!(extract_fn_only(name), Some("function".to_string()));
}
#[test]
#[serial]
fn test_profiling_enable_disable_profiling() {
}
#[test]
#[serial]
fn test_profiling_profile_paths() {
let paths = ProfilePaths::get();
assert!(
paths.time.ends_with(".folded"),
"Time path should end with .folded"
);
assert!(
paths.memory.ends_with("-memory.folded"),
"Memory path should end with -memory.folded"
);
let re = Regex::new(r"\d{8}-\d{6}\.folded$").unwrap();
assert!(
re.is_match(&paths.time),
"Time path should contain timestamp in YYYYmmdd-HHMMSS format"
);
}
}