Explore using measureme for profiling the interpreter

[jasonwilliams]

Blog Post

https://blog.rust-lang.org/inside-rust/2020/02/25/intro-rustc-self-profile.html

Tool location

https://github.com/rust-lang/measureme

Where to ask for more info

https://rust-lang.zulipchat.com/#narrow/stream/187831-t-compiler.2Fwg-self-profile

Conversation

Wesley Wiser: So the measureme docs actually look ok lol
https://docs.rs/measureme/0.7.1/measureme/

Wesley Wiser: The gist is that in your program, you'll create an instance of Profiler and pass that around to places that want to record things

Jason Williams: right

Jason Williams: Is it possible to have that in our program but not be compiled when releasing to the public?
How does that work?

Wesley Wiser: There's two basic kinds of events: instantaneous and start/stop. You probably are just interested in start/stop.

Wesley Wiser: So what rustc does is here https://github.com/rust-lang/rust/blob/0f72ce1b271b40a5652049362e6aab5914f7b1d3/src/librustc_data_structures/profiling.rs#L167

Wesley Wiser: When you specify -Zself-profile, then profiler is a Some(Arc(Profiler)) and when you don't, it's just None.

Wesley Wiser: All of the places we match on the enum use #[cold] to tell the compiler that calling into the profiler code is unlikely.

Wesley Wiser: I don't know that actually improves performance that much, but somebody decided to do it.

Wesley Wiser: The other thing you could do is gate using the Profiler behind a cargo feature flag

Wesley Wiser: When the flag is enabled, you compile with the profiler and call it and when the feature flag is not enabled, you have an empty dummy implementation that is just no ops. rustc should completely optimize that away.

Jason Williams: Thanks, so normally we want to measure the whole process (rather than small bits) is this the right tool for this?

Jason Williams: So like, pass in some JS and see how long it takes from start (lexing) to finsihing (printing some output)

Jason Williams: and see the calls being made in the flamegraph

Jason Williams: (actually time we're not worried about time as we use criterion for that, so this would just be callstacks)

Wesley Wiser: Yeah, you can definitely do that (it's pretty much how rustc uses it). The main thing I'll point out is that this isn't like perf where we periodically capture backtraces from your application, it's very much event driven. You have to instrument the application to time the things you care about.

Wesley Wiser: The downside is that you have to do that manually. The upside is that you can skip things you don't care about. You're also not limited to just seeing actual backtraces, you can see "semantic backtraces".

So for example, you could actually see "lexing", "parsing", "jitting", "evaluation", "gc", etc in your flamegraphs instead of having to infer that from backtraces.

Example

fn lex(&self, s: &str) -> TokenStream {
  let _timer = self.profiler.start_recording_interval_event(...);

  //your code here
 // and it stops the event when the _timer is dropped.
}

Wesley Wiser: It's not too bad IMO. There's a bit of ceremony to creating the labels because we don't use plain &strs for performance reasons. We have StringIds and EventIds which are basically just placeholders for strings. That makes it very cheap for us to de-duplicate them so you don't end up with huge trace files or spending a lot of time writing to disk.

Wesley Wiser: What I'd recommend is having your own Profiler type in your application where it internally uses our API and exposes the simplest thing you need for the rest of your application. This also gives you just one place where you have to handle the "is it enabled or not" bit.

[jasonwilliams]

Using a profiler which only compiles when we pass the feature flag

#![allow(missing_copy_implementations, missing_debug_implementations)]

pub use measureme;
#[cfg(feature = "profiler")]
pub struct MyProfiler {
    profiler: Arc<measureme::Profiler>,
}

#[cfg(feature = "profiler")]
impl MyProfiler {
    pub fn start_event(&self, label: &str) -> ProfileEventGuard {
        profiler.start_recording_interval_event()
    }
}

#[cfg(not(feature = "profiler"))]
pub struct MyProfiler;

#[cfg(not(feature = "profiler"))]
impl MyProfiler {
    pub fn start_event(&self, _label: &str) -> () {
        ()
    }
}

When the profiler feature isn't enabled, you get a 0-byte struct and empty functions which should inline away into nothing. When the feature is enabled though, you get the real thing and the calling code doesn't have to care about the feature flag.