Creating a very simple benchmarking macro for function calls

help
1

I need to profile the time taken by some functions (more than 1ms execution time) to run, but on production, not on development like the solutions I found.

Of course I could do:

time_before = get_time_ns();
my_function();
time_after = get_time_ns();
difference = time_after - time_before;

but this is boring to do on lots of functions. I thought about a macro that inserts that before and after the function, and then I could simply do

profile!(my_function(arg1, arg2, ...));

but how should I store the returned value? I think there would also be problems if the call is of the type:

profile!(object.my_function(arg1, arg2, ...))

Is it possible to create a macro that does what I want? Actually I don't think I even need to match for functions speficically, maybe match against the literal text inside the macro, an then simple execute this text as a line between the time measurements.

There's also the problem of when I need to measure

let r = object.my_function(arg1, arg2, ...)

but I think this could be translated to

let r = {
    time_before = get_time_ns();
    let r = my_function();
    time_after = get_time_ns();
    difference = time_after - time_before;
    r
}

but there's still the issue of returning the time difference. Returning a pair of the function result + time difference is ok but not the best. Maybe the macro could have 2 arguments:

profile!(variable_name, object.my_function(arg1, arg2, ...))

which translates to

let variable_name: std::time::Duration;
let r = {
    time_before = get_time_ns();
    let r = my_function();
    time_after = get_time_ns();
    variable_name = time_after - time_before;
    r
}

Anyone has a better idea? And is it possible to implement this with macros?

2

That would work easy enough.

That actually wouldn't be an issue.

I think that wouldn't be a problem if you just did:

let (time_spent, r) = profile!(object.my_function(arg1, arg2, ...).

The issue with that is that there's no way to get the return result of object.my_function in that example. Your example generated code can't be used in expression position so you wouldn't be able to do this:

let result = profile!(time_spent, object.my_function());

You can't have the macro create a new variable in scope and also expand to an expression at the same time because creating a new variable in scope is a statement and returning a value requires being an expression. You could do this, but I don't think that's better than returning the (time_spent, result) pair:

profile!(time_spent, my_result, object.my_function());

Here's a first pass macro for returning a pair of std::time::Duration and the function result (playground):

#![allow(warnings)]

macro_rules! profile {
    ($($token:tt)+) => {
        {
            let _instant = std::time::Instant::now();
            let _result = {
                $($token)+
            };
            
            (_instant.elapsed(), _result)
        }
    }
}

fn main() {
    let (dur, result) = profile!(my_func());
    
    dbg!(dur.as_millis(), result);
    
    let (dur, result) = profile!(format!("{:?}", Test(16)));
    
    dbg!(dur.as_nanos(), result);
}

#[derive(Debug)]
struct Test(u8);

fn my_func() -> i32 {
    std::thread::sleep_ms(304);
    49
}

As another option, if you want a fully featured solution for logging the amount of time spent doing different things you could look into the tracing library. It sounds like you're looking for something simpler, though.

That lets you create spans where it keeps track of the time you spent inside the span.

3

Would it be possible to use perf or another profiler. You can enable debuginfo in release mode by adding the following to Cargo.toml:

[profile.release]
debug = true
4

Benchmarking is very sensitive task and it's hard to check all necessary conditions before it. I've seen many people accidentally got benchmark of their allocator, OS thread scheduler, and the L1 instruction cache performance instead of the code they care. Try change the order of your benchmark, it can even flip the result.

So, don't benchmark by hand. Use proper library which handle all of them. I use criterion and it works well.

5

@Hyeonu do you mean that my code can falsely benchmark things? How could that happen?

6

If I understood correctly, criterion is used to benchmark. That is, it runs functions lots of times and take averages and etc.

What I need is to measure time elapsed for a function call, in live code. Not something very very precise. On my tests I got measurements as low as of 0.001ms which is enough for me even if it's not 100% accurate.

I didn't find a library that could take the time elapsed between a function call so I made a very very simple one, that you call like this:

let elapsed;
let result = profile!(elapsed, function_call(arg1, arg2));
print("time elapsed: {}, function result: {}", elapsed.as_micros(), result));

Here's my implementation:

#[macro_export]
macro_rules! profile {
    ($variable_name:tt, $expression:expr) => {
        {
            let start = std::time::Instant::now();
            let r = $expression;
            $variable_name = start.elapsed();
            r
        }
    };
    ($variable_name:tt, $block:block) => {
        {
            let start = std::time::Instant::now();
            let r = $block;
            $variable_name = start.elapsed();
            r
        }
    };
}

it matches block codes and expressions. What you think of it?

7

For just printing how long a step took, I'd not use a macro, but instead a type implementing Drop. Something vaguely like:

struct Timer {
  start: Instant,
  message: &'static str,
}
impl Drop for Timer {
  fn drop(self) {
      println!(". {} took {}", self.message, now-self.start);
  }
}

fn example() {
  let t = Timer::new("silly example");
  // Do some work, and when it leaves scope the timer tells you how long it took.
}
2 Likes
8

This topic was automatically closed 90 days after the last reply. We invite you to open a new topic if you have further questions or comments.