Profile arbitrary spans

[chrisduerr]

I was wondering if there's a way to add arbitrary spans to puffin. It would be nice to just do the following:

let scope = puffin::profile_scope!("slow_code");

// ...

drop(scope);

While in a lot of scenarios function and scope profiling is sufficient, there are some performance intervals that aren't easily measured using that methodology. Say something starts in the middle of one function and ends in the middle of another for example.

Being able to insert events with arbitrary start/end times might work too, would just require timing things myself.

[v0x0g]

I'm not sure what you mean by this - you can already profile custom scopes with the example code you gave, using puffin::profile_scope!("name");.

I'm guessing you would like to be able to store the scope object into a variable, and then be able to manually drop it when you wish? There are two options for this:

1: Force the scope to be nested

You can put the profile_scope!() call inside a nested block, and then the scope will be limited to the block and it will automatically end the scope once control leaves the block.

{
    profile_scope!("slow_code");
    // ...
    // No need to call drop()
}

Here's an example of me using it in my actual code:

    fn process_worker_render(&mut self, ctx: &Context) {
        profile_function!(); // Profiles the entire function's scope

        let Some(res) = self.integration.try_recv_render() else { return; };
        let Ok(render) = res else { return; };

        {
            profile_scope!("update_tex"); // Limited to the scope where I update the texture
            let opts = TextureOptions {
                magnification: TextureFilter::Nearest,
                minification: TextureFilter::Linear,
                wrap_mode: TextureWrapMode::ClampToEdge,
            };
            match &mut self.render_buf_tex {
                None => {
                    profile_scope!("tex_load"); // Profiles loading the texture
                    self.render_buf_tex = Some(ctx.load_texture("render_buffer_texture", render.img, opts))
                }
                Some(tex) => {
                    profile_scope!("tex_set"); // Profiles setting the texture
                    tex.set(render.img, opts)
                }
            }
        }

        self.render_stats = render.stats;
    }

2: Manually create the puffin scope

Either call the macro and then use cargo-expand to expand it out until you get something that works, or just manually create the scope.

Here's an example of me creating a custom scope that profiles work segments of a parallel rayon loop - each batch of work gets one scope as opposed to every single iteration.

pixels.for_each_init(
                move || {
                    // Can't use puffin's macro because of macro hygiene :(
                    let profiler_scope = if puffin::are_scopes_on() {
                        static SCOPE_ID: std::sync::OnceLock<puffin::ScopeId> = std::sync::OnceLock::new();
                        let scope_id = SCOPE_ID.get_or_init(|| {
                            puffin::ThreadProfiler::call(|tp| {
                                let id = tp.register_named_scope(
                                    "inner",
                                    puffin::clean_function_name(puffin::current_function_name!()),
                                    puffin::short_file_name(file!()),
                                    line!(),
                                );
                                id
                            })
                        });
                        Some(puffin::ProfilerScope::new(*scope_id, ""))
                    } else {
                        None
                    };
                    
                    // Don't drop the profiling scope, so it gets stored for the entire duration of the work segment
                    profiler_scope
                },
                |(_scope), ..)| {
                    // All calls here gets profiled on the same scope
                },
            );

[chrisduerr]

What I want is basically 2), so I can have something I can store on a struct and drop manually whenever I want.

The code in your second example is just quite significant, I think it would be nice to be able to do this in a simple fashion? Returning a value from a macro isn't a hygiene issue, so I feel like this should be possible?

[v0x0g]

Returning a value from a macro isn't a hygiene issue, so I feel like this should be possible?

Yeah it is unfortunately, that's why I had to do my approach

macro_rules! profile_scope {
    ($name:expr) => {
        $crate::profile_scope!($name, "");
    };
    ($name:expr, $data:expr) => {
        let _profiler_scope = if $crate::are_scopes_on() {
            static SCOPE_ID: std::sync::OnceLock<$crate::ScopeId> = std::sync::OnceLock::new();
            let scope_id = SCOPE_ID.get_or_init(|| {
                $crate::ThreadProfiler::call(|tp| {
                    let id = tp.register_named_scope(
                        $name,
                        $crate::clean_function_name($crate::current_function_name!()),
                        $crate::short_file_name(file!()),
                        line!(),
                    );
                    id
                })
            });
            Some($crate::ProfilerScope::new(*scope_id, $data))
        } else {
            None
        };
    };
}

See how it creates the variable _profiler_scope. There's no way to access that because of hygiene. You could probably just create a simple macro to do it honestly, just copy the puffin one but make it take in a variable identifier so you can propagate the value up.

#[macro_export]
macro_rules! profile_scope {
    ($var:ident, $name:expr) => {
        $crate::profile_scope!($var, $name, "");
    };
    ($var:ident, $name:expr, $data:expr) => {
        let $var = if $crate::are_scopes_on() {
            static SCOPE_ID: std::sync::OnceLock<$crate::ScopeId> = std::sync::OnceLock::new();
            let scope_id = SCOPE_ID.get_or_init(|| {
                $crate::ThreadProfiler::call(|tp| {
                    let id = tp.register_named_scope(
                        $name,
                        $crate::clean_function_name($crate::current_function_name!()),
                        $crate::short_file_name(file!()),
                        line!(),
                    );
                    id
                })
            });
            Some($crate::ProfilerScope::new(*scope_id, $data))
        } else {
            None
        };
    };
}

This might work, I'm not sure

[chrisduerr]

See how it creates the variable _profiler_scope. There's no way to access that because of hygiene.

Why not? If you change it to double brackets so you have a proper block and then just put _profiler_scope on the last line then that should work fine, shouldn't it?

[v0x0g]

That's my point, sadly it doesn't work, because of macro hygiene.

The identifier _profiler_scope declared inside the macro has a different scope than the identifier _profiler_scope that you try to access inside of the function's body.

Think of it like a module - the macro creates it's own private module that the function cannot access and vice-versa. The only way we can do it is by telling the macro which identifier we want it ti use instead of creating it's own (hence we pass in the name).

Here is a demo showing it not working

See this book on rust macros for a great explanation as to why and how it's not allowed.

[chrisduerr]

This is what I was suggesting:
https://play.rust-lang.org/?version=stable&mode=debug&edition=2021&gist=4bf4688bfdf6d4e8f31e6d2b5e21d838

[v0x0g]

Oh yeah that works too! This should be what you want then:

#[macro_export]
macro_rules! profile_scope_custom {
    ($name:expr) => {
        $crate::profile_scope_custom!($name, "")
    };
    ($name:expr, $data:expr) => {
        if $crate::are_scopes_on() {
            static SCOPE_ID: std::sync::OnceLock<$crate::ScopeId> = std::sync::OnceLock::new();
            let scope_id = SCOPE_ID.get_or_init(|| {
                $crate::ThreadProfiler::call(|tp| {
                    let id = tp.register_named_scope(
                        $name,
                        $crate::clean_function_name($crate::current_function_name!()),
                        $crate::short_file_name(file!()),
                        line!(),
                    );
                    id
                })
            });
            Some($crate::ProfilerScope::new(*scope_id, $data))
        } else {
            None
        }
    };
}

[chrisduerr]

@v0x0g Any chance a macro like that could pop up in puffin? It doesn't sound like I'm the only one to ever ask for something like this.

[v0x0g]

@chrisduerr I have made #213 for you

We'll have to wait for one of the maintainers to merge it. Until then you can use my fork or just copy the implementation above.

Hope this helps!