Print out both accesses involved in a data race

[cbeuw]

Currently Miri throws a UB on the access that ultimately causes a data race, which is always the later one. It is not clear where the other access involved in the data race is in the source file.

error: Undefined Behavior: Data race detected between Write on Thread(id = 0, name = "main") and Write on Thread(id = 1) at alloc1 (current vector clock = VClock([5]), conflicting timestamp = VClock([0, 8]))
  --> src/lib.rs:21:18
   |
21 |         unsafe { V = 2 }
   |                  ^^^^^ Data race detected between Write on Thread(id = 0, name = "main") and Write on Thread(id = 1) at alloc1 (current vector clock = VClock([5]), conflicting timestamp = VClock([0, 8]))
   |
   = help: this indicates a bug in the program: it performed an invalid operation, and caused Undefined Behavior
   = help: see https://doc.rust-lang.org/nightly/reference/behavior-considered-undefined.html for further information
           
   = note: inside `tests::data_race` at src/lib.rs:21:18

Both TSan and Go's race detector print out the line numbers of both accesses involved in the data race, we'd like to do the same.

It shouldn't be too hard to implement, we just need to augment VTimestamp with the current Span from MiriEvalContext::cur_span()

miri/src/vector_clock.rs

Line 45 in aca3b3a

pub type VTimestamp = u32;

[RalfJung]

Stacked Borrows recently got some support for showing extra spans thanks to @saethlin; we probably want to reuse that -- in particular it doesn't use cur_span but tries to find a span "in the local crate".

Also, augmenting every timestamp might be a bit too expensive in terms of performance?

[saethlin]

I don't know that augmenting every timestamp would be too slow. TSan manages to report backtraces in a debug build for these races, and those backtraces are not small and we're only trying to report one measly span. If someone is interested in doing this, it's probably worth giving the naïve approach a shot. If it's too slow I already have some ideas.

[cbeuw]

Is there a way to get a backtrace in Miri, and how expensive would this be? Only showing one span is probably not too helpful

[saethlin]

ecx.generate_stacktrace(), or you may be interested in looking over this:

miri/src/helpers.rs

Lines 825 to 860 in dcaa7a7

	impl<'mir, 'tcx> Evaluator<'mir, 'tcx> {
	pub fn current_span(&self) -> CurrentSpan<'_, 'mir, 'tcx> {
	CurrentSpan { span: None, machine: self }
	}
	}
	/// A `CurrentSpan` should be created infrequently (ideally once) per interpreter step. It does
	/// nothing on creation, but when `CurrentSpan::get` is called, searches the current stack for the
	/// topmost frame which corresponds to a local crate, and returns the current span in that frame.
	/// The result of that search is cached so that later calls are approximately free.
	#[derive(Clone)]
	pub struct CurrentSpan<'a, 'mir, 'tcx> {
	span: Option<Span>,
	machine: &'a Evaluator<'mir, 'tcx>,
	}
	impl<'a, 'mir, 'tcx> CurrentSpan<'a, 'mir, 'tcx> {
	pub fn get(&mut self) -> Span {
	*self.span.get_or_insert_with(|| Self::current_span(self.machine))
	}
	#[inline(never)]
	fn current_span(machine: &Evaluator<'_, '_>) -> Span {
	machine
	.threads
	.active_thread_stack()
	.iter()
	.rev()
	.find(|frame| {
	let def_id = frame.instance.def_id();
	def_id.is_local() || machine.local_crates.contains(&def_id.krate)
	})
	.map(|frame| frame.current_span())
	.unwrap_or(rustc_span::DUMMY_SP)
	}
	}

[cbeuw]

@saethlin Thanks, that looks handy.

we just need to augment VTimestamp with the current Span from

I realised what I said wouldn't work, because

miri/src/concurrency/data_race.rs

Lines 32 to 36 in dcaa7a7

	//! The timestamps used in the data-race detector assign each sequence of non-atomic operations
	//! followed by a single atomic or concurrent operation a single timestamp.
	//! Write, Read, Write, ThreadJoin will be represented by a single timestamp value on a thread.
	//! This is because extra increment operations between the operations in the sequence are not
	//! required for accurate reporting of data-race values.

On a data race, we know the offending timestamp, but that could cover multiple spans so we won't be able to pinpoint a line

[ibraheemdev]

I was trying to debug a data race in https://github.com/ibraheemdev/seize and had it narrowed down to a simple test case with two threads. I wanted to see the order in which miri was interleaving the threads to narrow down the bug, but adding debug statements added extra synchronization that fixed the data race ;) I ended up having to use a thread-unsafe println shim to see the order without breaking it:

pub fn println(x: String) {
    unsafe {
        let mut f = std::fs::File::from_raw_fd(1);
        f.write_all(x.as_bytes()).unwrap();
        std::mem::forget(f);
    }
}

And I did manage to find the missing synchronization edge, but it would be nice if this was easier.

[saethlin]

but that could cover multiple spans so we won't be able to pinpoint a line

We could give each timestamp a start and end span. I wonder how many times when we report a diagnostic the start and end span would be the same.