Make frame spans appear on a separate trace line

[Stypox]

This PR changes tracing_chrome's tracing::Layer so that if a span has the "tracing_separate_thread" 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):

info_span!("frame", tracing_separate_thread = Empty, "{}", instance);

Also see the following discussion I had with @RalfJung

Is there no way to attach metadata we could use instead?

These 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. 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, but then it gets even more complicated).

// 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) 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.

// 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, "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).

// example of how the above solution would look like
info_span!("frame", tracing_separate_root = tracing::field::Empty, "{}", instance);

[rustbot]

r? @lcnr

rustbot has assigned @lcnr.
They will have a look at your PR within the next two weeks and either review your PR or reassign to another reviewer.

Use r? to explicitly pick a reviewer

[rustbot]

Some changes occurred to the CTFE machinery

cc @RalfJung, @oli-obk, @lcnr

Some changes occurred to the CTFE / Miri interpreter

cc @rust-lang/miri

The Miri subtree was changed

cc @rust-lang/miri

[RalfJung]

r? @RalfJung

[RalfJung]

Maybe tracing_root or so would be a better name?

tracing_separate_line was just the first thing that came to my mind without understanding anything about what actually happens or what the tracing terminology is.

[Stypox]

You initially suggested tracing_separate_root and I changed it to tracing_separate_line; I settled on tracing_separate_line because that's what can be observed in the UI, i.e. those spans appear on a separate line. I tried to think of better names but I believe there is no actual technical term: the documentation of the trace format (also cited there) just calls the field "id" which per se does not mean much, and the tracing_chrome crate calls it "root_id" which again does not mean much and is probably arbitrary.

[RalfJung]

The fact that it's a "line" is just a choice of that one UI though, right? Seems odd to hard-code it in the naming.

You can emit async events from different processes and different threads. Each async event has an additional required parameter id. We consider the events with the same category and id as events from the same event tree.

So maybe tracing_separate_thread?
(That makes me wonder whether we can use this to resolve rust-lang/miri#2266, but that's a separate discussion.)

[Stypox]

tracing_separate_thread works for me, thanks for the suggestion, I changed it and force-pushed

(That makes me wonder whether we can use this to resolve rust-lang/miri#2266, but that's a separate discussion.)

Actually, rust-lang/miri#2266 affects chrome traces too, the following image doesn't look very tree-like 😅 (collected on tests/fail/data_race/atomic_read_na_write_race1.rs).

I think we can fix this by passing tracing_thread = TracingThreadId(self.active_thread().0), and providing an empty implementation of tracing::field::Value for TracingThreadId (like Empty does). Then from tracing_chrome it would be possible to retrieve this value and use it as the thread ID ("tid"), which also make stuff appear on different lines in perfetto

As for rust-lang/miri#2266, I think we'd need to make some internal changes in the tracing Layer that does logging.

[Stypox]

Actually, I guess it would be useful to see which thread is currently active in the perfetto timeline at any time. This could be achieved by:

• splitting up all trace events/spans (except for "frame") into multiple trace lines, one for each virtual thread created by Miri, and logging events/spans on each line depending on the currently active thread ID (this would kind of work but we might encounter issues of high-level spans beginning on one line and ending on another if the active thread switched in the meantime)
• adding a separate trace line that just contains contiguous spans with name "thread" and argument "thread_id" that begin when a thread becomes active and end when a thread becomes inactive (this would be quite easy to do)

[RalfJung]

Let's discuss that on Zulip, this PR is an improvement on its own already.

[RalfJung]

Thanks!
@bors r+ rollup

[bors]

📌 Commit 07a34c3 has been approved by RalfJung

It is now in the queue for this repository.