Track local frames incrementally during execution #2647

saethlin · 2022-11-04T00:07:37Z

#2646 currently introduces a performance regression. This change removes that regression, and provides a minor perf improvement.

The existing lazy strategy for tracking the span we want to display is as efficient as it is only because we often create a CurrentSpan then never call .get(). Most of the calls to the before_memory_read and before_memory_write hooks do not create any event that we store in AllocHistory. But data races are totally different, any memory read or write may race, so every call to those hooks needs to access to the current local span.

So this changes to a strategy where we update some state in a Thread and FrameExtra incrementally, upon entering and existing each function call.

Before:

Benchmark 1: cargo +miri miri run --manifest-path /home/ben/miri/bench-cargo-miri/backtraces/Cargo.toml
  Time (mean ± σ):      5.532 s ±  0.022 s    [User: 5.444 s, System: 0.073 s]
  Range (min … max):    5.516 s …  5.569 s    5 runs
 
Benchmark 1: cargo +miri miri run --manifest-path /home/ben/miri/bench-cargo-miri/mse/Cargo.toml
  Time (mean ± σ):     831.4 ms ±   3.0 ms    [User: 783.8 ms, System: 46.7 ms]
  Range (min … max):   828.7 ms … 836.1 ms    5 runs
 
Benchmark 1: cargo +miri miri run --manifest-path /home/ben/miri/bench-cargo-miri/serde1/Cargo.toml
  Time (mean ± σ):      1.975 s ±  0.021 s    [User: 1.914 s, System: 0.059 s]
  Range (min … max):    1.939 s …  1.990 s    5 runs
 
Benchmark 1: cargo +miri miri run --manifest-path /home/ben/miri/bench-cargo-miri/serde2/Cargo.toml
  Time (mean ± σ):      4.060 s ±  0.051 s    [User: 3.983 s, System: 0.071 s]
  Range (min … max):    3.972 s …  4.100 s    5 runs
 
Benchmark 1: cargo +miri miri run --manifest-path /home/ben/miri/bench-cargo-miri/slice-get-unchecked/Cargo.toml
  Time (mean ± σ):     784.9 ms ±   8.2 ms    [User: 746.5 ms, System: 37.7 ms]
  Range (min … max):   772.9 ms … 793.3 ms    5 runs
 
Benchmark 1: cargo +miri miri run --manifest-path /home/ben/miri/bench-cargo-miri/unicode/Cargo.toml
  Time (mean ± σ):      1.679 s ±  0.006 s    [User: 1.623 s, System: 0.055 s]
  Range (min … max):    1.673 s …  1.687 s    5 runs

After:

Benchmark 1: cargo +miri miri run --manifest-path /home/ben/miri/bench-cargo-miri/backtraces/Cargo.toml
  Time (mean ± σ):      5.330 s ±  0.037 s    [User: 5.232 s, System: 0.084 s]
  Range (min … max):    5.280 s …  5.383 s    5 runs
 
Benchmark 1: cargo +miri miri run --manifest-path /home/ben/miri/bench-cargo-miri/mse/Cargo.toml
  Time (mean ± σ):     818.9 ms ±   3.7 ms    [User: 776.8 ms, System: 41.3 ms]
  Range (min … max):   813.5 ms … 822.5 ms    5 runs
 
Benchmark 1: cargo +miri miri run --manifest-path /home/ben/miri/bench-cargo-miri/serde1/Cargo.toml
  Time (mean ± σ):      1.927 s ±  0.011 s    [User: 1.864 s, System: 0.061 s]
  Range (min … max):    1.917 s …  1.945 s    5 runs
 
Benchmark 1: cargo +miri miri run --manifest-path /home/ben/miri/bench-cargo-miri/serde2/Cargo.toml
  Time (mean ± σ):      3.974 s ±  0.020 s    [User: 3.893 s, System: 0.076 s]
  Range (min … max):    3.956 s …  4.004 s    5 runs
 
Benchmark 1: cargo +miri miri run --manifest-path /home/ben/miri/bench-cargo-miri/slice-get-unchecked/Cargo.toml
  Time (mean ± σ):     780.0 ms ±   5.3 ms    [User: 740.3 ms, System: 39.0 ms]
  Range (min … max):   771.2 ms … 784.5 ms    5 runs
 
Benchmark 1: cargo +miri miri run --manifest-path /home/ben/miri/bench-cargo-miri/unicode/Cargo.toml
  Time (mean ± σ):      1.643 s ±  0.007 s    [User: 1.584 s, System: 0.058 s]
  Range (min … max):    1.635 s …  1.654 s    5 runs

(This change is marginal, but the point is that it avoids a much more significant regression)

RalfJung · 2022-11-04T17:46:27Z

So those benchmarks are without #2646?

src/concurrency/thread.rs

src/helpers.rs

src/concurrency/thread.rs

src/machine.rs

saethlin · 2022-11-04T20:30:18Z

So those benchmarks are without #2646?

Yes. That PR adds extra work to the data race machinery in order to store the spans which has its own very small regression, so I wanted to keep the effects separate.

src/concurrency/thread.rs

saethlin · 2022-11-17T02:45:14Z

I think this is ready for re-review. Not quite ready for merge yet IMO, I think the cache invalidation might be a bit too aggressive based on a glance at the benchmarks...

src/machine.rs

src/concurrency/thread.rs

src/machine.rs

RalfJung · 2022-11-20T11:01:44Z

LGTM, what are the benchmarks saying? How could the cache be invalidated less aggressively than on each pop?

src/machine.rs

saethlin · 2022-11-21T04:42:05Z

How could the cache be invalidated less aggressively than on each pop?

I force-pushed after making this comment. Previously I was invalidating on every pop, not just pops of local frames. Most frames we create are in the standard library.

saethlin · 2022-11-21T05:10:23Z

what are the benchmarks saying?

I updated the PR description. We have the same marginal improvement.

RalfJung

All right so this is a simplification without perf loss. I like it, just some nits.

src/concurrency/thread.rs

bors · 2022-11-21T08:55:43Z

☔ The latest upstream changes (presumably #2684) made this pull request unmergeable. Please resolve the merge conflicts.

src/concurrency/thread.rs

src/helpers.rs

Co-authored-by: Ralf Jung <post@ralfj.de>

src/machine.rs

Co-authored-by: Ralf Jung <post@ralfj.de>

RalfJung · 2022-11-25T18:57:31Z

src/helpers.rs

-        let frame_idx = cmp::min(frame_idx, stack.len().saturating_sub(2));
-        stack.get(frame_idx).map(Frame::current_span).unwrap_or(rustc_span::DUMMY_SP)
+        self.top_user_relevant_frame()
+            .map(|frame_idx| cmp::min(frame_idx, self.stack().len() - 2))


This changes semantics I think?

Suggested change

.map(|frame_idx| cmp::min(frame_idx, self.stack().len() - 2))

.map(|frame_idx| cmp::min(frame_idx, self.stack().len().saturating_sub(2)))

Does it make sense to ask for the caller span (especially in an FnEntry retag) when we have one stack frame? I wrote this thinking "no, that would be a bug, so a crash would be good"

then it should be checked_sub(2).unwrap()

RalfJung · 2022-11-26T13:02:08Z

@bors r+

bors · 2022-11-26T13:02:10Z

📌 Commit 86052a9 has been approved by RalfJung

It is now in the queue for this repository.

bors · 2022-11-26T13:02:18Z

⌛ Testing commit 86052a9 with merge fa91fa7...

bors · 2022-11-26T13:24:22Z

☀️ Test successful - checks-actions
Approved by: RalfJung
Pushing fa91fa7 to master...

Data race spans Fixes #2205 This adds output to data race errors very similar to the spans we emit for Stacked Borrows errors. For example, from our test suite: ``` help: The Atomic Load on thread `<unnamed>` is here --> tests/fail/data_race/atomic_read_na_write_race1.rs:23:13 | 23 | ... (&*c.0).load(Ordering::SeqCst) //~ ERROR: Data race detected between Atomic Load on thread `<unnamed>` and Write o... | ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^ help: The Write on thread `<unnamed>` is here --> tests/fail/data_race/atomic_read_na_write_race1.rs:19:13 | 19 | *(c.0 as *mut usize) = 32; | ^^^^^^^^^^^^^^^^^^^^^^^^^``` ``` Because of #2647 this comes without a perf regression, according to our benchmarks.

Data race spans Fixes rust-lang/miri#2205 This adds output to data race errors very similar to the spans we emit for Stacked Borrows errors. For example, from our test suite: ``` help: The Atomic Load on thread `<unnamed>` is here --> tests/fail/data_race/atomic_read_na_write_race1.rs:23:13 | 23 | ... (&*c.0).load(Ordering::SeqCst) //~ ERROR: Data race detected between Atomic Load on thread `<unnamed>` and Write o... | ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^ help: The Write on thread `<unnamed>` is here --> tests/fail/data_race/atomic_read_na_write_race1.rs:19:13 | 19 | *(c.0 as *mut usize) = 32; | ^^^^^^^^^^^^^^^^^^^^^^^^^``` ``` Because of rust-lang/miri#2647 this comes without a perf regression, according to our benchmarks.

saethlin force-pushed the current-span branch from f0aa729 to cd78f83 Compare November 4, 2022 00:47

RalfJung reviewed Nov 4, 2022

View reviewed changes

src/concurrency/thread.rs Outdated Show resolved Hide resolved

RalfJung reviewed Nov 4, 2022

View reviewed changes

src/helpers.rs Outdated Show resolved Hide resolved

RalfJung reviewed Nov 4, 2022

View reviewed changes

src/concurrency/thread.rs Outdated Show resolved Hide resolved

RalfJung reviewed Nov 4, 2022

View reviewed changes

src/concurrency/thread.rs Outdated Show resolved Hide resolved

RalfJung reviewed Nov 4, 2022

View reviewed changes

src/machine.rs Outdated Show resolved Hide resolved

RalfJung reviewed Nov 5, 2022

View reviewed changes

src/concurrency/thread.rs Outdated Show resolved Hide resolved

saethlin mentioned this pull request Nov 6, 2022

Encapsulate interpreter stack(s) a bit better rust-lang/rust#104073

Closed

oli-obk reviewed Nov 17, 2022

View reviewed changes

src/machine.rs Outdated Show resolved Hide resolved

saethlin force-pushed the current-span branch from 8f184d3 to c9430d9 Compare November 17, 2022 15:26

RalfJung reviewed Nov 20, 2022

View reviewed changes

src/concurrency/thread.rs Outdated Show resolved Hide resolved

RalfJung reviewed Nov 20, 2022

View reviewed changes

src/machine.rs Outdated Show resolved Hide resolved

RalfJung reviewed Nov 20, 2022

View reviewed changes

src/machine.rs Outdated Show resolved Hide resolved

RalfJung reviewed Nov 20, 2022

View reviewed changes

src/machine.rs Outdated Show resolved Hide resolved

saethlin force-pushed the current-span branch from cbe3146 to cc99f2a Compare November 21, 2022 04:54

RalfJung reviewed Nov 21, 2022

View reviewed changes

src/concurrency/thread.rs Outdated Show resolved Hide resolved

src/concurrency/thread.rs Show resolved Hide resolved

src/concurrency/thread.rs Show resolved Hide resolved

src/concurrency/thread.rs Outdated Show resolved Hide resolved

Incrementally track which frame to use for diagnostics

5c72788

saethlin force-pushed the current-span branch from cc99f2a to 5c72788 Compare November 21, 2022 23:38

RalfJung reviewed Nov 22, 2022

View reviewed changes

src/concurrency/thread.rs Show resolved Hide resolved

RalfJung reviewed Nov 22, 2022

View reviewed changes

src/concurrency/thread.rs Outdated Show resolved Hide resolved

RalfJung reviewed Nov 22, 2022

View reviewed changes

src/helpers.rs Show resolved Hide resolved

RalfJung reviewed Nov 22, 2022

View reviewed changes

src/helpers.rs Show resolved Hide resolved

Document is_user_relevant

6f2f3d4

Co-authored-by: Ralf Jung <post@ralfj.de>

RalfJung reviewed Nov 22, 2022

View reviewed changes

src/machine.rs Show resolved Hide resolved

Update src/machine.rs

68223d6

Co-authored-by: Ralf Jung <post@ralfj.de>

RalfJung added the S-waiting-on-author Status: Waiting for the PR author to address review comments label Nov 23, 2022

Use None when the stack is empty

2c76f0c

RalfJung reviewed Nov 25, 2022

View reviewed changes

caller_span only makes sense when there are 2 frames on the stack

86052a9

bors merged commit fa91fa7 into rust-lang:master Nov 26, 2022

saethlin mentioned this pull request Dec 16, 2022

Data race spans #2646

Merged

saethlin deleted the current-span branch January 15, 2023 22:04

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Track local frames incrementally during execution #2647

Track local frames incrementally during execution #2647

saethlin commented Nov 4, 2022 •

edited

Loading

RalfJung commented Nov 4, 2022

saethlin commented Nov 4, 2022

saethlin commented Nov 17, 2022

RalfJung commented Nov 20, 2022

saethlin commented Nov 21, 2022

saethlin commented Nov 21, 2022

RalfJung left a comment

bors commented Nov 21, 2022

RalfJung Nov 25, 2022

saethlin Nov 25, 2022

RalfJung Nov 25, 2022

RalfJung commented Nov 26, 2022

bors commented Nov 26, 2022

bors commented Nov 26, 2022

bors commented Nov 26, 2022

	.map(\|frame_idx\| cmp::min(frame_idx, self.stack().len() - 2))
	.map(\|frame_idx\| cmp::min(frame_idx, self.stack().len().saturating_sub(2)))

Track local frames incrementally during execution #2647

Track local frames incrementally during execution #2647

Conversation

saethlin commented Nov 4, 2022 • edited Loading

RalfJung commented Nov 4, 2022

saethlin commented Nov 4, 2022

saethlin commented Nov 17, 2022

RalfJung commented Nov 20, 2022

saethlin commented Nov 21, 2022

saethlin commented Nov 21, 2022

RalfJung left a comment

Choose a reason for hiding this comment

bors commented Nov 21, 2022

RalfJung Nov 25, 2022

Choose a reason for hiding this comment

saethlin Nov 25, 2022

Choose a reason for hiding this comment

RalfJung Nov 25, 2022

Choose a reason for hiding this comment

RalfJung commented Nov 26, 2022

bors commented Nov 26, 2022

bors commented Nov 26, 2022

bors commented Nov 26, 2022

saethlin commented Nov 4, 2022 •

edited

Loading