loom icon indicating copy to clipboard operation
loom copied to clipboard

add `tracing` spans to `loom` diagnostics

Open hawkw opened this issue 5 years ago • 1 comments

Instead of logging a large header, what do you think about creating a separate tracing span 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...)

hawkw avatar Nov 05 '19 18:11 hawkw

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.

xunilrj avatar Jun 23 '20 19:06 xunilrj