Rollup merge of rust-lang#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>

Author: matthiaskrgr

compiler/rustc_const_eval/src/interpret/stack.rs

@@ -12,6 +12,7 @@ use rustc_middle::ty::{self, Ty, TyCtxt};
 use rustc_middle::{bug, mir};
 use rustc_mir_dataflow::impls::always_storage_live_locals;
 use rustc_span::Span;
+use tracing::field::Empty;
 use tracing::{info_span, instrument, trace};
 
 use super::{
@@ -396,7 +397,11 @@ impl<'tcx, M: Machine<'tcx>> InterpCx<'tcx, M> {
         // Finish things up.
         M::after_stack_push(self)?;
         self.frame_mut().loc = Left(mir::Location::START);
-        let span = info_span!("frame", "{}", instance);
+        // `tracing_separate_thread` is used to instruct the chrome_tracing [tracing::Layer] in Miri
+        // to put the "frame" span on a separate trace thread/line than other spans, to make the
+        // visualization in https://ui.perfetto.dev easier to interpret. It is set to a value of
+        // [tracing::field::Empty] so that other tracing layers (e.g. the logger) will ignore it.
+        let span = info_span!("frame", tracing_separate_thread = Empty, "{}", instance);
         self.frame_mut().tracing_span.enter(span);
 
         interp_ok(())

src/tools/miri/src/bin/log/tracing_chrome.rs

@@ -1,8 +1,18 @@
 // SPDX-License-Identifier: MIT
 // SPDX-FileCopyrightText: Copyright (c) 2020 Thoren Paulson
-//! This file is taken unmodified from the following link, except for file attributes and
-//! `extern crate` at the top.
-//! https://github.com/thoren-d/tracing-chrome/blob/7e2625ab4aeeef2f0ef9bde9d6258dd181c04472/src/lib.rs
+//! This file was initially taken from the following link:
+//! <https://github.com/thoren-d/tracing-chrome/blob/7e2625ab4aeeef2f0ef9bde9d6258dd181c04472/src/lib.rs>
+//!
+//! The precise changes that were made to the original file can be found in git history
+//! (`git log -- path/to/tracing_chrome.rs`), but in summary:
+//! - the file attributes were changed and `extern crate` was added at the top
+//! - if a tracing span has a field called "tracing_separate_thread", it will be given a separate
+//! span ID even in [TraceStyle::Threaded] mode, to make it appear on a separate line when viewing
+//! the trace in <https://ui.perfetto.dev>. This is the syntax to trigger this behavior:
+//!   ```rust
+//!   tracing::info_span!("my_span", tracing_separate_thread = tracing::field::Empty, /* ... */)
+//!   ```
+//!
 //! Depending on the tracing-chrome crate from crates.io is unfortunately not possible, since it
 //! depends on `tracing_core` which conflicts with rustc_private's `tracing_core` (meaning it would
 //! not be possible to use the [ChromeLayer] in a context that expects a [Layer] from
@@ -79,14 +89,26 @@ where
 }
 
 /// Decides how traces will be recorded.
+/// Also see <https://docs.google.com/document/d/1CvAClvFfyA5R-PhYUmn5OOQtYMH4h6I0nSsKchNAySU/preview#heading=h.jh64i9l3vwa1>
 #[derive(Default)]
 pub enum TraceStyle {
-    /// Traces will be recorded as a group of threads.
+    /// Traces will be recorded as a group of threads, and all spans on the same thread will appear
+    /// on a single trace line in <https://ui.perfetto.dev>.
     /// In this style, spans should be entered and exited on the same thread.
+    ///
+    /// If a tracing span has a field called "tracing_separate_thread", it will be given a separate
+    /// span ID even in this mode, to make it appear on a separate line when viewing the trace in
+    /// <https://ui.perfetto.dev>. This is the syntax to trigger this behavior:
+    /// ```rust
+    /// tracing::info_span!("my_span", tracing_separate_thread = tracing::field::Empty, /* ... */)
+    /// ```
+    /// [tracing::field::Empty] is used so that other tracing layers (e.g. the logger) will ignore
+    /// the "tracing_separate_thread" argument and not print out anything for it.
     #[default]
     Threaded,
 
-    /// Traces will recorded as a group of asynchronous operations.
+    /// Traces will recorded as a group of asynchronous operations. All spans will be given separate
+    /// span IDs and will appear on separate trace lines in <https://ui.perfetto.dev>.
     Async,
 }
 
@@ -497,31 +519,39 @@ where
         }
     }
 
-    fn get_root_id(span: SpanRef<S>) -> u64 {
-        span.scope()
-            .from_root()
-            .take(1)
-            .next()
-            .unwrap_or(span)
-            .id()
-            .into_u64()
+    fn get_root_id(&self, span: SpanRef<S>) -> Option<u64> {
+        match self.trace_style {
+            TraceStyle::Threaded => {
+                if span.fields().field("tracing_separate_thread").is_some() {
+                    // assign an independent "id" to spans with argument "tracing_separate_thread",
+                    // so they appear a separate trace line in trace visualization tools, see
+                    // https://docs.google.com/document/d/1CvAClvFfyA5R-PhYUmn5OOQtYMH4h6I0nSsKchNAySU/preview#heading=h.jh64i9l3vwa1
+                    Some(span.id().into_u64())
+                } else {
+                    None
+                }
+            },
+            TraceStyle::Async => Some(
+                span.scope()
+                    .from_root()
+                    .take(1)
+                    .next()
+                    .unwrap_or(span)
+                    .id()
+                    .into_u64()
+            ),
+        }
     }
 
     fn enter_span(&self, span: SpanRef<S>, ts: f64) {
         let callsite = self.get_callsite(EventOrSpan::Span(&span));
-        let root_id = match self.trace_style {
-            TraceStyle::Async => Some(ChromeLayer::get_root_id(span)),
-            _ => None,
-        };
+        let root_id = self.get_root_id(span);
         self.send_message(Message::Enter(ts, callsite, root_id));
     }
 
     fn exit_span(&self, span: SpanRef<S>, ts: f64) {
         let callsite = self.get_callsite(EventOrSpan::Span(&span));
-        let root_id = match self.trace_style {
-            TraceStyle::Async => Some(ChromeLayer::get_root_id(span)),
-            _ => None,
-        };
+        let root_id = self.get_root_id(span);
         self.send_message(Message::Exit(ts, callsite, root_id));
     }