Make "frame" spans go on a separate trace line than others #4451
Conversation
src/bin/log/tracing_chrome.rs
Outdated
| .id() | ||
| .into_u64() | ||
| ), | ||
| _ => if span.metadata().name() == "frame" { |
There was a problem hiding this comment.
I'm definitely not a fan of hard-coding a particular name here, that way lies total spaghetti code.
There was a problem hiding this comment.
Makes sense, I've made it more general
"frame" spans indicate stack frames in the interpreted program
Stypox
force-pushed
the
separate-frame-in-traces
branch
from
7b27a2f to
d7ec893
Compare
|
@rustbot ready |
|
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 |
|
I don't fully understand neither |
RalfJung
added
S-waiting-on-author
Yeah I agree, and the right way to do this would be to use the
The problem with 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 |
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.
I'm fine with adding that. No idea if it is useful.^^ Or maybe |
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.
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
I think |
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
Okay, makes sense.
I don't see how that could possibly help. |
|
Closing in favor of rust-lang/rust#143955 |
…fJung Make frame spans appear on a separate trace line This PR changes tracing_chrome's `tracing::Layer` so that if a span has the "tracing_separate_line" field as one of the span arguments, that span is put on a separate trace line. See rust-lang/miri#4451 for an earlier attempt and for screenshots explaining better what I mean by "separate trace line". This PR also makes the "frame" span use this feature (so it appears on a separate trace line, see rust-lang/miri#4451 for motivation), but passes `tracing::field::Empty` as the span parameter value so it is ignored by other tracing layers (e.g. the logger): ```rust info_span!("frame", tracing_separate_line = Empty, "{}", instance); ``` <details><summary>Also see the following discussion I had with ``@RalfJung</summary>`` > Is there no way to attach metadata we could use instead? [These](https://docs.rs/tracing-core/0.1.34/src/tracing_core/metadata.rs.html#57) are the **static** metadata items we can control about a span. We can't add more metadata outside of them. The most relevant are: - `name` (for the frame span it's currently "frame") - `target` which acts as the category (for the frame span it's currently "rustc_const_eval::interpret::stack" by default) - `fields` which contains a list of the *names* of each of the arguments passed to the `span!` macro (for the frame span it's currently ["message"], where "message" is the default identifier for data passed in the `format!` syntax) When the tracing code is called at runtime, the **dynamic** values of the arguments are collected into a [`ValueSet`](https://docs.rs/tracing-core/0.1.34/src/tracing_core/field.rs.html#166). Each argument value stored there corresponds with one of the static names stored in `fields` (see above). --- We have already determined that filtering out spans by `name` is not a good idea, and I would say the same goes for `target`. Both the `name` and the `target` fields are printed to stderr when `MIRI_LOG=` is enabled, so changing them to contain an identifier (e.g. "frame:tracing_separate_root" instead of "frame" as the name) would uselessly clutter the text logs (unless we add one more filter [there](https://github.com/rust-lang/rust/blob/master/compiler/rustc_log/src/lib.rs#L137), but then it gets even more complicated). ```rust // examples of how the above (problematic) solutions would look like info_span!("frame:tracing_separate_root", "{}", instance); info_span!(target: "tracing_separate_root", "frame", "{}", instance); ``` --- So that leaves us with `fields` and their runtime values. Now, my initial thought (inspired by [this comment](rust-lang/miri#4451 (comment))) was to use a field with the static name "tracing_separate_root" and with a dynamic boolean value of "true". In `tracing_chrome.rs` we can easily check if this field is true and act accordingly. This would work but then again this field would also be picked up by the logger when `MIRI_LOG=` is enabled, and would uselessly clutter the text logs. ```rust // example of how the above (problematic) solution would look like info_span!("frame", tracing_separate_root = true, "{}", instance); ``` --- To avoid cluttering the text logs, we can instead set "tracing_separate_root" to the dynamic value of `tracing::field::Empty`. Citing from [here](https://docs.rs/tracing/0.1.41/tracing/field/struct.Empty.html), "when a field’s value is `Empty`, it will not be recorded". "not being recorded" means that the field and its value won't be printed to stderr text logs, nor will it be printed by any other tracing layers that might be attached in the future. In `tracing_chrome.rs` we would still be able to check if "tracing_separate_root" is in the list of static `fields`, and act accordingly. So I believe this solution would effectively allow us to attach metadata to a span in a way that does not clutter logs and still allows being read in `tracing_chrome.rs`. If we ever wanted to pass arbitrary metadata (i.e. not just a present/not present flag), it would be possible with a custom `Empty` that also holds data and implement `Value` without doing anything ([like `Empty` does](https://docs.rs/tracing-core/0.1.34/src/tracing_core/field.rs.html#775)). ```rust // example of how the above solution would look like info_span!("frame", tracing_separate_root = tracing::field::Empty, "{}", instance); ``` </details>
Rollup merge of #143955 - Stypox:tracing-frame-filter, r=RalfJung Make frame spans appear on a separate trace line This PR changes tracing_chrome's `tracing::Layer` so that if a span has the "tracing_separate_line" field as one of the span arguments, that span is put on a separate trace line. See rust-lang/miri#4451 for an earlier attempt and for screenshots explaining better what I mean by "separate trace line". This PR also makes the "frame" span use this feature (so it appears on a separate trace line, see rust-lang/miri#4451 for motivation), but passes `tracing::field::Empty` as the span parameter value so it is ignored by other tracing layers (e.g. the logger): ```rust info_span!("frame", tracing_separate_line = Empty, "{}", instance); ``` <details><summary>Also see the following discussion I had with ``@RalfJung</summary>`` > Is there no way to attach metadata we could use instead? [These](https://docs.rs/tracing-core/0.1.34/src/tracing_core/metadata.rs.html#57) are the **static** metadata items we can control about a span. We can't add more metadata outside of them. The most relevant are: - `name` (for the frame span it's currently "frame") - `target` which acts as the category (for the frame span it's currently "rustc_const_eval::interpret::stack" by default) - `fields` which contains a list of the *names* of each of the arguments passed to the `span!` macro (for the frame span it's currently ["message"], where "message" is the default identifier for data passed in the `format!` syntax) When the tracing code is called at runtime, the **dynamic** values of the arguments are collected into a [`ValueSet`](https://docs.rs/tracing-core/0.1.34/src/tracing_core/field.rs.html#166). Each argument value stored there corresponds with one of the static names stored in `fields` (see above). --- We have already determined that filtering out spans by `name` is not a good idea, and I would say the same goes for `target`. Both the `name` and the `target` fields are printed to stderr when `MIRI_LOG=` is enabled, so changing them to contain an identifier (e.g. "frame:tracing_separate_root" instead of "frame" as the name) would uselessly clutter the text logs (unless we add one more filter [there](https://github.com/rust-lang/rust/blob/master/compiler/rustc_log/src/lib.rs#L137), but then it gets even more complicated). ```rust // examples of how the above (problematic) solutions would look like info_span!("frame:tracing_separate_root", "{}", instance); info_span!(target: "tracing_separate_root", "frame", "{}", instance); ``` --- So that leaves us with `fields` and their runtime values. Now, my initial thought (inspired by [this comment](rust-lang/miri#4451 (comment))) was to use a field with the static name "tracing_separate_root" and with a dynamic boolean value of "true". In `tracing_chrome.rs` we can easily check if this field is true and act accordingly. This would work but then again this field would also be picked up by the logger when `MIRI_LOG=` is enabled, and would uselessly clutter the text logs. ```rust // example of how the above (problematic) solution would look like info_span!("frame", tracing_separate_root = true, "{}", instance); ``` --- To avoid cluttering the text logs, we can instead set "tracing_separate_root" to the dynamic value of `tracing::field::Empty`. Citing from [here](https://docs.rs/tracing/0.1.41/tracing/field/struct.Empty.html), "when a field’s value is `Empty`, it will not be recorded". "not being recorded" means that the field and its value won't be printed to stderr text logs, nor will it be printed by any other tracing layers that might be attached in the future. In `tracing_chrome.rs` we would still be able to check if "tracing_separate_root" is in the list of static `fields`, and act accordingly. So I believe this solution would effectively allow us to attach metadata to a span in a way that does not clutter logs and still allows being read in `tracing_chrome.rs`. If we ever wanted to pass arbitrary metadata (i.e. not just a present/not present flag), it would be possible with a custom `Empty` that also holds data and implement `Value` without doing anything ([like `Empty` does](https://docs.rs/tracing-core/0.1.34/src/tracing_core/field.rs.html#775)). ```rust // example of how the above solution would look like info_span!("frame", tracing_separate_root = tracing::field::Empty, "{}", instance); ``` </details>
Make frame spans appear on a separate trace line This PR changes tracing_chrome's `tracing::Layer` so that if a span has the "tracing_separate_line" field as one of the span arguments, that span is put on a separate trace line. See #4451 for an earlier attempt and for screenshots explaining better what I mean by "separate trace line". This PR also makes the "frame" span use this feature (so it appears on a separate trace line, see #4451 for motivation), but passes `tracing::field::Empty` as the span parameter value so it is ignored by other tracing layers (e.g. the logger): ```rust info_span!("frame", tracing_separate_line = Empty, "{}", instance); ``` <details><summary>Also see the following discussion I had with ``@RalfJung</summary>`` > Is there no way to attach metadata we could use instead? [These](https://docs.rs/tracing-core/0.1.34/src/tracing_core/metadata.rs.html#57) are the **static** metadata items we can control about a span. We can't add more metadata outside of them. The most relevant are: - `name` (for the frame span it's currently "frame") - `target` which acts as the category (for the frame span it's currently "rustc_const_eval::interpret::stack" by default) - `fields` which contains a list of the *names* of each of the arguments passed to the `span!` macro (for the frame span it's currently ["message"], where "message" is the default identifier for data passed in the `format!` syntax) When the tracing code is called at runtime, the **dynamic** values of the arguments are collected into a [`ValueSet`](https://docs.rs/tracing-core/0.1.34/src/tracing_core/field.rs.html#166). Each argument value stored there corresponds with one of the static names stored in `fields` (see above). --- We have already determined that filtering out spans by `name` is not a good idea, and I would say the same goes for `target`. Both the `name` and the `target` fields are printed to stderr when `MIRI_LOG=` is enabled, so changing them to contain an identifier (e.g. "frame:tracing_separate_root" instead of "frame" as the name) would uselessly clutter the text logs (unless we add one more filter [there](https://github.com/rust-lang/rust/blob/master/compiler/rustc_log/src/lib.rs#L137), but then it gets even more complicated). ```rust // examples of how the above (problematic) solutions would look like info_span!("frame:tracing_separate_root", "{}", instance); info_span!(target: "tracing_separate_root", "frame", "{}", instance); ``` --- So that leaves us with `fields` and their runtime values. Now, my initial thought (inspired by [this comment](#4451 (comment))) was to use a field with the static name "tracing_separate_root" and with a dynamic boolean value of "true". In `tracing_chrome.rs` we can easily check if this field is true and act accordingly. This would work but then again this field would also be picked up by the logger when `MIRI_LOG=` is enabled, and would uselessly clutter the text logs. ```rust // example of how the above (problematic) solution would look like info_span!("frame", tracing_separate_root = true, "{}", instance); ``` --- To avoid cluttering the text logs, we can instead set "tracing_separate_root" to the dynamic value of `tracing::field::Empty`. Citing from [here](https://docs.rs/tracing/0.1.41/tracing/field/struct.Empty.html), "when a field’s value is `Empty`, it will not be recorded". "not being recorded" means that the field and its value won't be printed to stderr text logs, nor will it be printed by any other tracing layers that might be attached in the future. In `tracing_chrome.rs` we would still be able to check if "tracing_separate_root" is in the list of static `fields`, and act accordingly. So I believe this solution would effectively allow us to attach metadata to a span in a way that does not clutter logs and still allows being read in `tracing_chrome.rs`. If we ever wanted to pass arbitrary metadata (i.e. not just a present/not present flag), it would be possible with a custom `Empty` that also holds data and implement `Value` without doing anything ([like `Empty` does](https://docs.rs/tracing-core/0.1.34/src/tracing_core/field.rs.html#775)). ```rust // example of how the above solution would look like info_span!("frame", tracing_separate_root = tracing::field::Empty, "{}", instance); ``` </details>
…fJung Make frame spans appear on a separate trace line This PR changes tracing_chrome's `tracing::Layer` so that if a span has the "tracing_separate_line" field as one of the span arguments, that span is put on a separate trace line. See rust-lang/miri#4451 for an earlier attempt and for screenshots explaining better what I mean by "separate trace line". This PR also makes the "frame" span use this feature (so it appears on a separate trace line, see rust-lang/miri#4451 for motivation), but passes `tracing::field::Empty` as the span parameter value so it is ignored by other tracing layers (e.g. the logger): ```rust info_span!("frame", tracing_separate_line = Empty, "{}", instance); ``` <details><summary>Also see the following discussion I had with ``@RalfJung</summary>`` > Is there no way to attach metadata we could use instead? [These](https://docs.rs/tracing-core/0.1.34/src/tracing_core/metadata.rs.html#57) are the **static** metadata items we can control about a span. We can't add more metadata outside of them. The most relevant are: - `name` (for the frame span it's currently "frame") - `target` which acts as the category (for the frame span it's currently "rustc_const_eval::interpret::stack" by default) - `fields` which contains a list of the *names* of each of the arguments passed to the `span!` macro (for the frame span it's currently ["message"], where "message" is the default identifier for data passed in the `format!` syntax) When the tracing code is called at runtime, the **dynamic** values of the arguments are collected into a [`ValueSet`](https://docs.rs/tracing-core/0.1.34/src/tracing_core/field.rs.html#166). Each argument value stored there corresponds with one of the static names stored in `fields` (see above). --- We have already determined that filtering out spans by `name` is not a good idea, and I would say the same goes for `target`. Both the `name` and the `target` fields are printed to stderr when `MIRI_LOG=` is enabled, so changing them to contain an identifier (e.g. "frame:tracing_separate_root" instead of "frame" as the name) would uselessly clutter the text logs (unless we add one more filter [there](https://github.com/rust-lang/rust/blob/master/compiler/rustc_log/src/lib.rs#L137), but then it gets even more complicated). ```rust // examples of how the above (problematic) solutions would look like info_span!("frame:tracing_separate_root", "{}", instance); info_span!(target: "tracing_separate_root", "frame", "{}", instance); ``` --- So that leaves us with `fields` and their runtime values. Now, my initial thought (inspired by [this comment](rust-lang/miri#4451 (comment))) was to use a field with the static name "tracing_separate_root" and with a dynamic boolean value of "true". In `tracing_chrome.rs` we can easily check if this field is true and act accordingly. This would work but then again this field would also be picked up by the logger when `MIRI_LOG=` is enabled, and would uselessly clutter the text logs. ```rust // example of how the above (problematic) solution would look like info_span!("frame", tracing_separate_root = true, "{}", instance); ``` --- To avoid cluttering the text logs, we can instead set "tracing_separate_root" to the dynamic value of `tracing::field::Empty`. Citing from [here](https://docs.rs/tracing/0.1.41/tracing/field/struct.Empty.html), "when a field’s value is `Empty`, it will not be recorded". "not being recorded" means that the field and its value won't be printed to stderr text logs, nor will it be printed by any other tracing layers that might be attached in the future. In `tracing_chrome.rs` we would still be able to check if "tracing_separate_root" is in the list of static `fields`, and act accordingly. So I believe this solution would effectively allow us to attach metadata to a span in a way that does not clutter logs and still allows being read in `tracing_chrome.rs`. If we ever wanted to pass arbitrary metadata (i.e. not just a present/not present flag), it would be possible with a custom `Empty` that also holds data and implement `Value` without doing anything ([like `Empty` does](https://docs.rs/tracing-core/0.1.34/src/tracing_core/field.rs.html#775)). ```rust // example of how the above solution would look like info_span!("frame", tracing_separate_root = tracing::field::Empty, "{}", instance); ``` </details>
tracing_chromesupports two styles of data that are shown differently in https://ui.perfetto.dev: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<- this was doneTraceStylelikeThreadedWithExceptions(Vec<&'static str>)instead of a hardcodedif. I don't think we're going to need this for other spans though.