loom
loom copied to clipboard
add `tracing` spans to `loom` diagnostics
Instead of logging a large header, what do you think about creating a separate
tracingspan representing each iteration, with the iteration number as a field? That way, everything recorded during that iteration will be annotated with the iteration number.This isn't necessarily a blocker for merging this PR, so it might be worth doing in a follow-up branch.
Originally posted by @hawkw in https://github.com/tokio-rs/loom/pull/91
Follow-up from #91.
I think ideally, it would be fantastic if we had a span structure like this for all events loom records:
test{name=my_loom_test}:execution{iter=15}:thread{id=1}: something happened...
(note that recording the test name may be difficult without asking the user to provide it, or providing a test macro...)
I don't know if this counts, but I made a small modification that improves the log (at least from my perspective). It is far from complete, though.
See at: https://github.com/xunilrj/loom/commit/1524c63dd29fa8204b09aa87d4abb7621fcd5d05
And the diagnostic generated is:
> clear && RUST_LOG=trace LOOM_LOCATION=1 LOOM_CHECKPOINT_INTERVAL=1 LOOM_LOG=1 RUSTFLAGS="--cfg loom --cfg loom_nightly --cfg loom_show_code" cargo test -- --nocapture
...
================== Iteration 1 ==================
TRACE loom::rt::execution > Switch to Thread 1
TRACE loom::rt::atomic > src/lib.rs:59:42: return=0 : let current_head = self.head.load(Ordering::SeqCst);
TRACE loom::rt::atomic > src/lib.rs:61:29: prev=0, next=140298327986160 : match self.head.compare_exchange(
TRACE loom::rt::execution > Switch to Thread 0
TRACE loom::rt::execution > Switch to Thread 2
TRACE loom::rt::atomic > src/lib.rs:88:46: return=0 : let current_head_ptr = self.head.load(Ordering::SeqCst);
TRACE loom::rt::atomic > src/lib.rs:88:46: return=140298327986160 : let current_head_ptr = self.head.load(Ordering::SeqCst);
TRACE loom::rt::atomic > src/lib.rs:93:63: return=0 : let current_head_next_ptr = current_head.next.load(Ordering::SeqCst);
TRACE loom::rt::atomic > src/lib.rs:94:33: prev=140298327986160, next=0 : match self.head.compare_exchange(
TRACE loom::rt::execution > Switch to Thread 0
================== Iteration 2 ==================
...
To understand the log:
1 - I am using https://crates.io/crates/log; 2 - the "src/lib.rs:59:42" is the source code location that called the atomic. In this case it was a ptr.load(); 3 - the "return=0" part varies. Here is the result of the .load(). It returned a null pointer; 4 - the "let current_head = self.head.load(Ordering::SeqCst);" part is the actual code that called the atomic. Can be turned on/off by a feature.
If this is useful, I can continue and create the PR. Any suggestion is also welcomed.