Add tracing spans to borrow tracker functions

[Stypox]

I should have added tracing spans to all relevant functions in borrow_tracker/mod.rs. So e.g. I skipped simple constructors (e.g. new_ptr) and debugging stuff (give_pointer_debug_name and print_borrow_state). I didn't go deeper into the tree/stacked subfolders, as it seems like all calls to the borrow checkers pass through borrow_tracker/mod.rs (let me know if I'm wrong on this, or if you need some more specific statistics about the functions in the checkers implementations).

Here are two traces for ./tests/pass/hello.rs (the latter was obtained with -Zmiri-tree-borrows). The tracing spans still only account for ~40% of the total time, so I will have to investigate where the rest of the time is spent. trace-stacked-borrows.zip trace-tree-borrows.zip

This PR also adds an alternative enter_trace_span! that does not depend on the Machine trait (unlike rustc_const_eval::enter_trace_span!) and that instead relies on #[cfg(feature = "tracing")]. I can open a separate PR just with that commit if that's preferred.

[RalfJung]

Shouldn't all these be called something like borrow_tracker::on_stack_pop or so? Just on_stack_pop is kind of unspecific.

Is there some way in the analysis tools to group all the borrow_tracker spans together?

[Stypox]

Shouldn't all these be called something like borrow_tracker::on_stack_pop or so? Just on_stack_pop is kind of unspecific.

The spans are automatically assigned the borrow_tracker category/target¹ because they are in a module with that name, but since the category is not shown in the main visualization on Perfetto (but only after you click on a span) I agree it's better to prepend borrow_tracker::. I updated the code.

@rustbot ready

Is there some way in the analysis tools to group all the borrow_tracker spans together?

In Perfetto it is a bit cumbersome to do for some reason, but it can be done like this:

• in the top bar, insert : to enter SQL mode
• insert SELECT * FROM slice WHERE category LIKE "%borrow_tracker%" (to choose by category/target) or SELECT * FROM slice WHERE category LIKE "%borrow_tracker%" (to choose by name)
• on the right, click on "Show debug track", give it a name, and then you will get a new row in the visualization containing only borrow_tracker spans

Another nice way to put spans with different category/target on different lines in the visualization is:

• execute the query SELECT * FROM slice like before
• on the right, click on "Show debug track", give it a name, and select "category" under the "pivot" menu

_{¹ in the tracing crate, the category is called "target", see here}

[RalfJung]

In Perfetto it is a bit cumbersome to do for some reason, but it can be done like this:

Okay so despite this being cumbersome you think it is best to give each span here a separate... name or whatever the term is?

[Stypox]

I think it is better to have borrow_tracker::on_stack_pop as a name instead of just on_stack_pop, since the name is shown in various places in the Perfetto UI (e.g. the main tree view, but also the flamegraph or the various tables), while the category is only shown after clicking on a span.

[RalfJung]

That's not what I was asking.

I was asking whether it is a good idea to give each span a separate name.
Because the obvious alternative is to give all spans the same name: just "borrow_tracker".

(I don't know if "name" is the right term. What's the thing called that is the argument to enter_trace_span!?)

[Stypox]

Oh, now I understand, sorry 😬

I was about to say that giving all spans the same name might make it harder to debug slowdowns within the borrow tracker (because, again, one would need to click on each span to understand which function it originated from). But then I found out that if we add a fun = "on_stack_pop" argument to the span macro, then it is possible to make Perfetto show a separate line with the "fun" value as the span name. This can be done by selecting a span, clicking on the "fun" argument on the right, and clicking on "Visualize argument values".

So I would suggest turning all:

let _span = enter_trace_span!("borrow_tracker::on_stack_pop", ...)

into

let _span = enter_trace_span!("borrow_tracker", fun = "on_stack_pop", ...)

This is then what can then be viewed from Perfetto:

[Stypox]

Maybe "borrow_tracker_fun" would be a better name for the argument instead of just "fun", so that when you do "Visualize argument values" only the spans with "borrow_tracker_fun" would be shown in the new line and not all spans with "fun" which we might add in the future, but this is a detail anyway.

I really feel like Perfetto's UI is powerful but quite unintuitive, and the docs don't explain much, so I will have to write a guide on how to use Perfetto for our purposes at some point and link it from Contributing.md :-)

[RalfJung]

I don't have a strong opinion either way here, I was just trying to explore the design space a bit.^^

So I would suggest turning all:

That works for me.

[RalfJung]

@rustbot author

[rustbot]

Reminder, once the PR becomes ready for a review, use @rustbot ready.

[Stypox]

I pushed a commit that makes all spans have the same name and pass the function name as a span argument. Since the tracing calls are now a bit verbose, I also thought about adding a new macro rule to shorten the code a bit. Let me know if the added complexity is worth the shorter code, and if yes I will turn this into a commit:

Diff

(note: I wanted to use concat!(stringify!($name), "_fun") instead of just $name as the argument name, however that's only possible in more recent versions of the tracing library (not in 0.1.37 that rustc is using), see the { RESOURCE_NAME } syntax here).

diff --git a/src/helpers.rs b/src/helpers.rs
index c9137bad2..f607fdfe8 100644
--- a/src/helpers.rs
+++ b/src/helpers.rs
@@ -1446,10 +1446,14 @@ pub struct MaybeEnteredTraceSpan {
 /// check whether the "tracing" feature is enabled, unlike from the rustc_const_eval codebase.
 #[macro_export]
 macro_rules! enter_trace_span {
+    ($name:ident :: $subname:ident $($tt:tt)*) => {{
+        enter_trace_span!(stringify!($name), $name = %stringify!(subname) $($tt)*)
+    }};
+
     ($($tt:tt)*) => {
         $crate::MaybeEnteredTraceSpan {
             #[cfg(feature = "tracing")]
             _entered_span: tracing::info_span!($($tt)*).entered()
         }
-    }
+    };
 }
diff --git a/src/borrow_tracker/mod.rs b/src/borrow_tracker/mod.rs
index 04f228e7a..24238ee5c 100644
--- a/src/borrow_tracker/mod.rs
+++ b/src/borrow_tracker/mod.rs
@@ -260,13 +260,7 @@ impl GlobalStateInner {
         kind: MemoryKind,
         machine: &MiriMachine<'_>,
     ) -> AllocState {
-        let _span = enter_trace_span!(
-            "borrow_tracker",
-            borrow_tracker_fun = %"new_allocation",
-            ?id,
-            ?alloc_size,
-            ?kind,
-        );
+        let _span = enter_trace_span!(borrow_tracker::new_allocation, ?id, ?alloc_size, ?kind);
         match self.borrow_tracker_method {
             BorrowTrackerMethod::StackedBorrows =>
                 AllocState::StackedBorrows(Box::new(RefCell::new(Stacks::new_allocation(
@@ -287,12 +281,7 @@ pub trait EvalContextExt<'tcx>: crate::MiriInterpCxExt<'tcx> {
         kind: RetagKind,
         val: &ImmTy<'tcx>,
     ) -> InterpResult<'tcx, ImmTy<'tcx>> {
-        let _span = enter_trace_span!(
-            "borrow_tracker",
-            borrow_tracker_fun = %"retag_ptr_value",
-            ?kind,
-            ?val.layout,
-        );
+        let _span = enter_trace_span!(borrow_tracker::retag_ptr_value, ?kind, ?val.layout);
         let this = self.eval_context_mut();
         let method = this.machine.borrow_tracker.as_ref().unwrap().borrow().borrow_tracker_method;
         match method {
@@ -306,12 +295,7 @@ pub trait EvalContextExt<'tcx>: crate::MiriInterpCxExt<'tcx> {
         kind: RetagKind,
         place: &PlaceTy<'tcx>,
     ) -> InterpResult<'tcx> {
-        let _span = enter_trace_span!(
-            "borrow_tracker",
-            borrow_tracker_fun = %"retag_place_contents",
-            ?kind,
-            ?place,
-        );
+        let _span = enter_trace_span!(borrow_tracker::retag_place_contents, ?kind, ?place);
         let this = self.eval_context_mut();
         let method = this.machine.borrow_tracker.as_ref().unwrap().borrow().borrow_tracker_method;
         match method {
@@ -321,8 +305,7 @@ pub trait EvalContextExt<'tcx>: crate::MiriInterpCxExt<'tcx> {
     }
 
     fn protect_place(&mut self, place: &MPlaceTy<'tcx>) -> InterpResult<'tcx, MPlaceTy<'tcx>> {
-        let _span =
-            enter_trace_span!("borrow_tracker", borrow_tracker_fun = %"protect_place", ?place);
+        let _span = enter_trace_span!(borrow_tracker::protect_place, ?place);
         let this = self.eval_context_mut();
         let method = this.machine.borrow_tracker.as_ref().unwrap().borrow().borrow_tracker_method;
         match method {
@@ -333,8 +316,7 @@ pub trait EvalContextExt<'tcx>: crate::MiriInterpCxExt<'tcx> {
 
     fn expose_tag(&self, alloc_id: AllocId, tag: BorTag) -> InterpResult<'tcx> {
         let _span = enter_trace_span!(
-            "borrow_tracker",
-            borrow_tracker_fun = %"expose_tag",
+            borrow_tracker::expose_tag,
             alloc_id = alloc_id.0,
             tag = tag.0,
         );
@@ -381,7 +363,7 @@ pub trait EvalContextExt<'tcx>: crate::MiriInterpCxExt<'tcx> {
         &self,
         frame: &Frame<'tcx, Provenance, FrameExtra<'tcx>>,
     ) -> InterpResult<'tcx> {
-        let _span = enter_trace_span!("borrow_tracker", borrow_tracker_fun = %"on_stack_pop");
+        let _span = enter_trace_span!(borrow_tracker::on_stack_pop);
         let this = self.eval_context_ref();
         let borrow_tracker = this.machine.borrow_tracker.as_ref().unwrap();
         // The body of this loop needs `borrow_tracker` immutably
@@ -459,11 +441,7 @@ impl AllocState {
         range: AllocRange,
         machine: &MiriMachine<'tcx>,
     ) -> InterpResult<'tcx> {
-        let _span = enter_trace_span!(
-            "borrow_tracker",
-            borrow_tracker_fun = %"before_memory_read",
-            alloc_id = alloc_id.0
-        );
+        let _span = enter_trace_span!(borrow_tracker::before_memory_read, alloc_id = alloc_id.0);
         match self {
             AllocState::StackedBorrows(sb) =>
                 sb.borrow_mut().before_memory_read(alloc_id, prov_extra, range, machine),
@@ -485,11 +463,7 @@ impl AllocState {
         range: AllocRange,
         machine: &MiriMachine<'tcx>,
     ) -> InterpResult<'tcx> {
-        let _span = enter_trace_span!(
-            "borrow_tracker",
-            borrow_tracker_fun = %"before_memory_write",
-            alloc_id = alloc_id.0
-        );
+        let _span = enter_trace_span!(borrow_tracker::before_memory_write, alloc_id = alloc_id.0);
         match self {
             AllocState::StackedBorrows(sb) =>
                 sb.get_mut().before_memory_write(alloc_id, prov_extra, range, machine),
@@ -512,8 +486,7 @@ impl AllocState {
         machine: &MiriMachine<'tcx>,
     ) -> InterpResult<'tcx> {
         let _span = enter_trace_span!(
-            "borrow_tracker",
-            borrow_tracker_fun = %"before_memory_deallocation",
+            borrow_tracker::before_memory_deallocation,
             alloc_id = alloc_id.0
         );
         match self {
@@ -525,8 +498,7 @@ impl AllocState {
     }
 
     pub fn remove_unreachable_tags(&self, tags: &FxHashSet<BorTag>) {
-        let _span =
-            enter_trace_span!("borrow_tracker", borrow_tracker_fun = %"remove_unreachable_tags");
+        let _span = enter_trace_span!(borrow_tracker::remove_unreachable_tags);
         match self {
             AllocState::StackedBorrows(sb) => sb.borrow_mut().remove_unreachable_tags(tags),
             AllocState::TreeBorrows(tb) => tb.borrow_mut().remove_unreachable_tags(tags),
@@ -542,8 +514,7 @@ impl AllocState {
         alloc_id: AllocId, // diagnostics
     ) -> InterpResult<'tcx> {
         let _span = enter_trace_span!(
-            "borrow_tracker",
-            borrow_tracker_fun = %"release_protector",
+            borrow_tracker::release_protector,
             alloc_id = alloc_id.0,
             tag = tag.0
         );
@@ -557,7 +528,7 @@ impl AllocState {
 
 impl VisitProvenance for AllocState {
     fn visit_provenance(&self, visit: &mut VisitWith<'_>) {
-        let _span = enter_trace_span!("borrow_tracker", borrow_tracker_fun = %"visit_provenance");
+        let _span = enter_trace_span!(borrow_tracker::visit_provenance);
         match self {
             AllocState::StackedBorrows(sb) => sb.visit_provenance(visit),
             AllocState::TreeBorrows(tb) => tb.visit_provenance(visit),

[RalfJung]

What does the % mean?

[Stypox]

Citing from here:

• The ? sigil is shorthand that specifies a field should be recorded using its fmt::Debug implementation

• The % sigil operates similarly, but indicates that the value should be recorded using its fmt::Display implementation

[RalfJung]

I like that macro, but it needs a comment explaining its usage.

[Stypox]

Done

[RalfJung]

LGTM, thanks! Please fix CI, and do you want to clean up the history a bit? 5 commits seems like a lot for this change.

[RalfJung]

@rustbot author

[Stypox]

@rustbot ready