Make "frame" spans go on a separate trace line than others

[Stypox]

tracing_chrome supports two styles of data that are shown differently in https://ui.perfetto.dev:

• "Threaded", i.e. each thread has its own trace line in the UI, each line with a tree structure of nested spans. Since Miri is single-threaded, this is equivalent to having a single trace line with all of the spans.

• "Async", i.e. each span has its own trace line in the UI (this is also the representation the Firefox profiler uses).

I believe the "Threaded" style generally allows for more insights as argued here, however it's a bit cumbersome to use because the "frame" spans (i.e. those that indicate stack frames in the interpreted program) are very big with respect to other spans and are therefore in the way. So this PR puts them (and only them) on a separate trace line:

Ideally this kind of filtering should be doable from the trace viewer UI, but I don't think https://ui.perfetto.dev supports anything like that.

Let me know if I should make the changes more general, e.g. by adding a new TraceStyle like ThreadedWithExceptions(Vec<&'static str>) instead of a hardcoded if. I don't think we're going to need this for other spans though. <- this was done

[RalfJung]

I'm definitely not a fan of hard-coding a particular name here, that way lies total spaghetti code.

[Stypox]

Makes sense, I've made it more general

[Stypox]

@rustbot ready

[RalfJung]

You just moved the "frame" name checking to a different file, I don't see how this is better.

The "frame" span itself should have appropriate metadata that controls this behavior, rather than special-casing the name after it has already entered the logging system. IOW, the code here is in charge of saying what happens with frame.

[RalfJung]

I don't fully understand neither tracing nor the visualizations you show, but it seems like you might want the perf-related spans in one "line" and the debugging-related ones in another? frame is just an example here for the one debugging span that is actually enabled in regular rustc build, but there is nothing very special about it.

[Stypox]

The "frame" span itself should have appropriate metadata that controls this behavior, rather than special-casing the name after it has already entered the logging system. IOW, the code here is in charge of saying what happens with frame.

Yeah I agree, and the right way to do this would be to use the target parameter when creating spans, which allows setting a category to the span and defaults to the module name. However, the data still appears all on the same "line" when visualizing it in Perfetto, and while there are ways to separate it out like explained in this comment, it's quite cumbersome to setup the UI manually every time you open a trace. Speaking of which, I looked for ways to save a Perfetto workspace to file (in order to be able to restore the queries and the configuration later), but it seems like there is no way to do so.

frame is just an example here for the one debugging span that is actually enabled in regular rustc build, but there is nothing very special about it.

The problem with frame is that, unlike other spans, it's long-lived and can grow big nested trees, which makes interpreting the visualization more cumbersome. But yeah other than this there is nothing special about it.

---

One idea me and Max had during our last meeting is to allow enabling/disabling spans from specific modules at runtime, in the same way that text logs from specific modules be enabled/disabled using the MIRI_LOG= env var. Do you think this would be useful? It would be quite easy to add (e.g. using another environment variable and then tracing::EnvFilter).

[RalfJung]

Yeah I agree, and the right way to do this would be to use the target parameter when creating spans, which allows setting a category to the span and defaults to the module name. However, the data still appears all on the same "line" when visualizing it in Perfetto, and while there are ways to separate it out like explained in #4452 (comment), it's quite cumbersome to setup the UI manually every time you open a trace. Speaking of which, I looked for ways to save a Perfetto workspace to file (in order to be able to restore the queries and the configuration later), but it seems like there is no way to do so.

I have no idea what you are talking about or how that relates to my comment that you are replying to.^^

What I mean is that this should become something like this pseudo-code

let span = info_span!("frame", tracing_separate_root=true, "{}", instance);

I have no idea how flexible the tracing system is, but this is clearly information that the span should provide ("treat me as a separate root", or whatever the right terminology is here), not something that should be hard-coded in Miri by matching on the span's name.

One idea me and Max had during our last meeting is to allow enabling/disabling spans from specific modules at runtime, in the same way that text logs from specific modules be enabled/disabled using the MIRI_LOG= env var. Do you think this would be useful? It would be quite easy to add (e.g. using another environment variable and then tracing::EnvFilter).

I'm fine with adding that. No idea if it is useful.^^

Or maybe frame should just be excluded from tracing entirely, if there's a way to do that (controlled by the code that creates the span ofc, not controlled by Miri)? Originally I thought maybe it could be useful to explore how much time Miri spends in which function, but maybe that's not currently very useful.

[Stypox]

I have no idea what you are talking about or how that relates to my comment that you are replying to.^^

I meant that the intended way to tell some spans apart from some others, as far as I understand from the tracing library documentation, is by putting them in separate categories. Then the unwanted span categories can be filtered out when analyzing the trace file, e.g. with Perfetto's SQL queries.

What I mean is that this should become something like this pseudo-code let span = info_span!("frame", tracing_separate_root=true, "{}", instance);

Yeah I agree that would be the best solution, however the "tracing_separate_root=true" would act as a parameter being logged, and would be printed together with the logs when MIRI_LOG is enabled. And then I would need to change tracing-chrome to treat that parameter as a hint to put the span on a separate "line". But yeah this would work.

Or maybe frame should just be excluded from tracing entirely, if there's a way to do that (controlled by the code that creates the span ofc, not controlled by Miri)? Originally I thought maybe it could be useful to explore how much time Miri spends in which function, but maybe that's not currently very useful.

I think frame can be useful, e.g. in #4297 to understand which parts of the random number generator are slow for Miri. But if we wanted to exclude it from tracing, we could do so by reintroducing the Machine::TRACING_ENABLED constant.

[RalfJung]

Yeah I agree that would be the best solution, however the "tracing_separate_root=true" would act as a parameter being logged, and would be printed together with the logs when MIRI_LOG is enabled. And then I would need to change tracing-chrome to treat that parameter as a hint to put the span on a separate "line". But yeah this would work.

We have have to have a call since I feel like we are still talking completely past each other and I don't know how to make myself more clear. :/

I didn't suggest it to be a parameter to be logged. I suggested this to be some distinguisher on the span, some metadata, that later layers can check. I don't know what the syntax of that could/should look like -- remember that I know nothing about the concrete details of the tracing library, I am talking purely in terms of general high-level concepts here. I am relying on you to map that to tracing concepts; do not expect whatever I say to already be phrased in terms of the tracing API.

I think frame can be useful, e.g. in #4297 to understand which parts of the random number generator are slow for Miri.

Okay, makes sense.

But if we wanted to exclude it from tracing, we could do so by reintroducing the Machine::TRACING_ENABLED constant.

I don't see how that could possibly help.

[Stypox]

Closing in favor of rust-lang/rust#143955