Simple Profiler in Rust

Question

I am writing code for a simple 'Profiler', using a struct, a hashmap, Options, and some methods. I call the profiler at many places in my code with the functions names, and the hashmap gets fed, linking function names with their performances. A function can be called many times, and the total running time is increased, as one would expect.

It does compile and does what I want, but the aim is also to learn to write proper Rust, and I guess I overused things like as_mut(), as_ref(), and mutable references altogether. I am pretty sure there is room for improvement, and I was wondering if anyone could have a look at my code, which is pretty straightforward. I spent some time to make it work, but I am not satisfied yet. You can find the code below. Maybe it is even possible to improve the code in order to avoid adding this extra argument 'profiler' to all the functions, and automatically profile functions by adding a magic line above their definition, as it is done for unit/reg tests, such as:

#[profile_this_function]
fn func()

Thanks for any help and time.

Here is the profiler code:

use std::collections::HashMap;
use std::time::{SystemTime, UNIX_EPOCH};
use std::fmt;
use std::thread;
use std::time::Duration;
//struct Profiler
// methods : start(tag_string), stop(tag_string)
// trait: fmt::Display
fn get_curr_time_epoch() -> f64 {
 let time_now: f64 = (SystemTime::now().duration_since(UNIX_EPOCH).expect("Time went backwards").as_millis() as f64) / 1000.;
 //println!("get_curr_time_epoch: {}", time_now);
 return time_now;
}
struct ProfilerTimer {
 total_time: f64,
 start: Option<f64>,
}
pub struct Profiler {
 profiler_stats_option : Option<HashMap<String, ProfilerTimer>>, // = None; //HashMap::new();
}
impl Profiler {
 pub fn new() -> Profiler {
 return Profiler {profiler_stats_option : Some(HashMap::new())};
 }
 pub fn start(& mut self, tag: &String) {
 if self.profiler_stats_option.is_none() { panic!("Error : profiler_stats must be initialised with new()");}
 let mut profiler_stats: &mut HashMap<String, ProfilerTimer> = self.profiler_stats_option.as_mut().unwrap();
 let b_key_present: bool = profiler_stats.contains_key(tag);
 match b_key_present {
 false => {&profiler_stats.insert(String::from(tag), 
 ProfilerTimer {total_time : 0., start : None});}
 true => {}
 }
 let ProfilerTimer_curr: &ProfilerTimer = &mut profiler_stats.get(tag).unwrap(); // profiler_stats[tag];
 let b_is_running: bool = (ProfilerTimer_curr.start.is_some());
 if b_is_running {panic!("Internal Error: Key is already running. Did you forget to call profiler_stop ?");}
 // Start the chrono
 let start: f64 = get_curr_time_epoch();
 let profiler_timer_tmp: ProfilerTimer = ProfilerTimer {
 total_time: ProfilerTimer_curr.total_time, start: Some(start)};
 profiler_stats.insert( tag.to_string(), profiler_timer_tmp);
 }
 pub fn stop(& mut self, tag: &String) {
 let stop: f64 = get_curr_time_epoch();
 if self.profiler_stats_option.is_none() { panic!("Error : profiler_stats must be initialised with new()");}
 let mut profiler_stats: &mut HashMap<String, ProfilerTimer> = self.profiler_stats_option.as_mut().unwrap();
 let b_key_present: bool = profiler_stats.contains_key(tag);
 match b_key_present {
 false => {panic!("Internal Error: Key is missing. Did you call profiler_start beforehand ?");}
 true => {}
 }
 let ProfilerTimer_curr: &ProfilerTimer = &mut profiler_stats.get(tag).unwrap(); // profiler_stats[tag];
 let b_is_running: bool = ProfilerTimer_curr.start.is_some();
 if !b_is_running {panic!("Internal Error: Key is not running. Did you call profiler_start beforehand ?");}
 let delta: f64 = stop - ProfilerTimer_curr.start.unwrap();
 if delta < 0. {panic!("Internal error: Negative delta.")}
 let profiler_timer_tmp: ProfilerTimer = ProfilerTimer 
 {total_time: ProfilerTimer_curr.total_time + delta, start: None};
 profiler_stats.insert( tag.to_string(), profiler_timer_tmp);
 }
}
impl fmt::Display for Profiler {
 fn fmt(&self, f: &mut fmt::Formatter) -> fmt::Result {
 println!("profiler_print_stats:");
 if self.profiler_stats_option.is_none() {
 return write!(f, "None");
 }
 else {
 if self.profiler_stats_option.is_none() { panic!("Error : profiler_stats must be initialised with new()");}
 let profiler_stats: &HashMap<String, ProfilerTimer> = self.profiler_stats_option.as_ref().unwrap();
 for (key, value) in profiler_stats.into_iter() {
 write!(f, "{} : {} s\n", key, f64::round(value.total_time * 1000.) / 1000.);
 }
 write!(f, "")
 }
 }
}
fn my_func_to_be_profiled(profiler: &mut Profiler, dummy_arg: f64)
{
 profiler.start(&String::from("my_func_to_be_profiled"));
 // Do something..
 //
 thread::sleep(Duration::from_millis(1234)); 
 profiler.stop(&String::from("my_func_to_be_profiled"));
}
fn main() {
 let mut profiler: Profiler = Profiler::new();
 my_func_to_be_profiled(&mut profiler, 3.14);
 println!("Profiler : {}", profiler);
}

• Richard Neumann: profiler_stats_option is implemented as an Option, but is never set to None. Consider using a HashMap directly and getting rid of the unnecessary checks for is_none().
• Richard Neumann: Also, if you don't explicitly want to reinvent the wheel, consider using one of the existing profiling crates, such as profiling.
• user24615633: Thanks for the comment Richard. Actually, I do want to reinvent the wheel, as it is both a way to learn Rust and to avoid any external dependencies. I still think I overused as_ref() and as_mut(), and there are ways to implement this in a simpler, maybe "rusty" way ?

Answer 1

Follow established naming and style guidelines

The compiler will warn about some of these (such as let ProfilerTimer_curr: not being snake_case), but cargo fmt will do even more fixes (such as unnecessary whitespace in & mut self or in profiler_stats_option : Option<HashMap<String, ProfilerTimer>>).

Use cargo clippy and listen to compiler warnings

The compiler already gives some warnings, namely:

• unnecessary mut in let mut profiler_stats: &mut HashMap<String, ProfilerTimer> = self.profiler_stats_option.as_mut().unwrap();
• unnecessary parentheses: an expression of the form (value) can usually be value

Clippy will warn about many more common mistakes and unidiomatic things in your code, namely:

• return value; at the end of a function should be just value
• for i in collection.into_iter() should be for i in collection
• println! in a Display impl should be writeln!
• and some other minor details

Let the compiler figure types out for you

Most of the time, declaring the type of a variable manually doesn't increase clarity, so avoid it. Example:

let profiler_timer_tmp: ProfilerTimer = ProfilerTimer {
 total_time: profiler_timer_curr.total_time,
 start: Some(start),
};

Here, it is obvious that the type is ProfilerTimer, no need to say that twice.

Remove commented out code

No need to keep old debug code around.

Matching on a bool should be done with plain if

It's shorter, clearer and doesn't need an empty arm.

Use &str instead of &String for arguments

A &String can be easily coerced into a &str, but not the other way around (which is why profiler.start(&String::from("my_func_to_be_profiled")); is necessary instead of profiler.start("my_func_to_be_profiled");), but since the &String is behind an immutable reference, it cannot be mutated and offers no better functionality compared to &str.

Redundant checks

Consider the following code:

if self.profiler_stats_option.is_none() {
 write!(f, "None")
} else {
 if self.profiler_stats_option.is_none() {
 panic!("Error: profiler_stats must be initialised with new()");
 }
 ...
}

Checking the same condition in the else again is redundant and should be removed.

Encapsulation

In an actual use case, the Profiler type would be in its own crate or at least its own module. Then, Profiler::new is the only way to create a profiler, profiler_stats_option is always Some and the Option can be removed (as Richard Neumann already mentioned in a comment).

unwrap_or instead of inserting first

In the following snippet, you do not need to insert the value first:

if !profiler_stats.contains_key(tag) {
 profiler_stats.insert(
 String::from(tag),
 ProfilerTimer {
 total_time: 0.,
 start: None,
 },
 );
}
let profiler_timer_curr = profiler_stats.get(tag).unwrap();

Use unwrap_or instead:

let profiler_timer_curr = profiler_stats.get(tag).unwrap_or(&ProfilerTimer {
 total_time: 0.,
 start: None,
});

New code

use std::collections::HashMap;
use std::fmt;
use std::thread;
use std::time::{Duration, SystemTime, UNIX_EPOCH};
fn get_curr_time_epoch() -> f64 {
 (SystemTime::now()
 .duration_since(UNIX_EPOCH)
 .expect("Time went backwards")
 .as_millis() as f64)
 / 1000.
}
struct ProfilerTimer {
 total_time: f64,
 start: Option<f64>,
}
pub struct Profiler {
 profiler_stats_option: HashMap<String, ProfilerTimer>,
}
impl Profiler {
 pub fn new() -> Profiler {
 Profiler {
 profiler_stats_option: HashMap::new(),
 }
 }
 pub fn start(&mut self, tag: &str) {
 let profiler_stats = &mut self.profiler_stats_option;
 let profiler_timer_curr = profiler_stats.get(tag).unwrap_or(&ProfilerTimer {
 total_time: 0.,
 start: None,
 });
 if profiler_timer_curr.start.is_some() {
 panic!("Internal Error: Key is already running. Did you forget to call profiler_stop?");
 }
 profiler_stats.insert(
 tag.to_string(),
 ProfilerTimer {
 total_time: profiler_timer_curr.total_time,
 start: Some(get_curr_time_epoch()),
 },
 );
 }
 pub fn stop(&mut self, tag: &str) {
 let stop = get_curr_time_epoch();
 let profiler_stats = &mut self.profiler_stats_option;
 if !profiler_stats.contains_key(tag) {
 panic!("Internal Error: Key is missing. Did you call profiler_start beforehand?");
 }
 let profiler_timer_curr = profiler_stats.get(tag).unwrap();
 if profiler_timer_curr.start.is_none() {
 panic!("Internal Error: Key is not running. Did you call profiler_start beforehand?");
 }
 let delta = stop - profiler_timer_curr.start.unwrap();
 if delta < 0. {
 panic!("Internal error: Negative delta.")
 }
 let profiler_timer_tmp = ProfilerTimer {
 total_time: profiler_timer_curr.total_time + delta,
 start: None,
 };
 profiler_stats.insert(tag.to_string(), profiler_timer_tmp);
 }
}
impl fmt::Display for Profiler {
 fn fmt(&self, f: &mut fmt::Formatter) -> fmt::Result {
 writeln!(f, "profiler_print_stats:")?;
 for (key, value) in &self.profiler_stats_option {
 writeln!(
 f,
 "{} : {} s",
 key,
 f64::round(value.total_time * 1000.) / 1000.
 )?;
 }
 write!(f, "")
 }
}
fn my_func_to_be_profiled(profiler: &mut Profiler, _dummy_arg: f64) {
 profiler.start("my_func_to_be_profiled");
 // Do something..
 //
 thread::sleep(Duration::from_millis(1234));
 profiler.stop("my_func_to_be_profiled");
}
fn main() {
 let mut profiler = Profiler::new();
 my_func_to_be_profiled(&mut profiler, 3.1);
 println!("Profiler: {}", profiler);
}

Further considerations

Easier usage

• Consider adding a method to get the time from a tag directly for an user of the profiler.
• Consider replacing the panic!s with Results to give a callar more flexibility how to handle the error.
• For your example of a #[profile_this_function] attribute, look into procedural macros. Such a macro could then modify the function to call the respective profiler methods.