Improve logging #91

nkaretnikov · 2019-10-29T16:47:09Z

No description provided.

nkaretnikov · 2019-10-29T16:52:12Z

This adds a bunch of prints whenever execution can be accessed, which provide a bit more visibility into what threads are actually doing.

This is only enabled when LOOM_LOG=1 is set, but I wonder if these messages should be sent to stderr or be prefixed with something to make it easier to filter them out.

What do you think?

nkaretnikov · 2019-10-29T16:56:34Z

Fixed the issue spotted by cargo fmt --all -- --check and force-pushed.

nkaretnikov · 2019-10-29T17:17:14Z

Rebased on the current master and force-pushed again.

hawkw · 2019-10-29T19:27:40Z

@nkaretnikov what do you think about using a logging library like tracing or log rather than println!? That would give users more sophisticated options for filtering which messages should be displayed.

hawkw · 2019-10-29T19:28:12Z

Also, what do you think about including a prefix such as the name of the test (which, IIRC, should be the name of the thread the test is running on)?

hawkw

I left some notes. In general, I think it would be very helpful to provide some kind of identifier for the various objects in loom that now emit log messages. This would allow users to track which object these messages refer to.

hawkw · 2019-10-29T19:31:21Z

src/rt/alloc.rs

@@ -15,6 +15,10 @@ pub(super) struct State {
 /// Track a raw allocation
 pub(crate) fn alloc(ptr: *mut u8) {
    rt::execution(|execution| {
+        if execution.log {
+            println!("alloc");


Take it or leave it, but what do you think of

Suggested change

println!("alloc");

println!("alloc {:p}", ptr);

using the fmt::Pointer formatter? Although printing the memory location doesn't provide a lot of information on its own, if we print it in dealloc as well, users can at least match pairs of alloc and dealloc calls.

hawkw · 2019-10-29T19:31:40Z

src/rt/alloc.rs

-        );
+    let allocation = rt::execution(|execution| {
+        if execution.log {
+            println!("dealloc");


Similarly, maybe

Suggested change

println!("dealloc");

println!("dealloc {:p}", ptr);

hawkw · 2019-10-29T19:32:34Z

src/rt/arc.rs

@@ -60,6 +64,10 @@ impl Arc {
        self.obj.branch(Action::RefInc);

        rt::execution(|execution| {
+            if execution.log {
+                println!("Arc::ref_inc");


WDYT about including the ref count after increment in this message? We'd have to move the message down to where the ref count is incremented.

hawkw · 2019-10-29T19:32:48Z

src/rt/arc.rs

@@ -90,6 +102,10 @@ impl Arc {
        self.obj.branch(Action::RefDec);

        rt::execution(|execution| {
+            if execution.log {
+                println!("Arc::ref_dec");


Similarly, maybe this should include the ref count after decrement?

hawkw · 2019-10-29T19:34:39Z

src/rt/arc.rs

@@ -45,6 +45,10 @@ pub(super) enum Action {
 impl Arc {
    pub(crate) fn new() -> Arc {
        rt::execution(|execution| {
+            if execution.log {
+                println!("Arc::new");


Perhaps we should include something identifying the Arc (maybe the internal loom object ID or a memory address?) in this message and the other messages in this module?

Although those don't convey a whole lot of semantic information about which Arc in the program the messages refer to, they do allow matching the Arc::new, Arc::ref_inc, Arc::ref_decmessages and so on. Paired with logging in the code under test, users _could_ probably track differentArc`s in their code based on an identifier added by loom.

hawkw · 2019-10-29T19:35:40Z

src/rt/atomic.rs

@@ -128,6 +148,10 @@ pub(crate) fn fence(order: Ordering) {
    );

    rt::synchronize(|execution| {
+        if execution.log {
+            println!("fence");


should this include what the ordering of the fence was?

hawkw · 2019-10-29T19:37:11Z

src/rt/mod.rs

@@ -43,6 +43,10 @@ where
    F: FnOnce() + 'static,
 {
    execution(|execution| {
+        if execution.log {
+            println!("spawn");


Similarly to my other comments, I think it would be very helpful to include something identifying the thread to these messages. I think we can use the loom internal object ID for this.

nkaretnikov · 2019-11-02T01:22:34Z

@hawkw Agreed on every point, looking into it. Thanks for the feedback!

nkaretnikov · 2019-11-03T23:22:23Z

Used the following code for testing. It should trigger all trace points either directly or implicitly.

Printing additional data in src/cell/causal.rs and src/thread.rs requires
adding the std::fmt::Debug bound to methods. This is imposed on users, so I
decided not to do it.

Not using #[instrument] from tracing for the same reason.

Not using the function_name crate because it doesn't print the name of a struct
when used with methods.

Various log levels are supported (see the tracing docs), for example:

LOOM_LOG=trace
LOOM_LOG=info
LOOM_LOG=warn

No messages are printed when the environment variable is not set, same as before.

use loom;

use loom::cell::CausalCell;

use std::alloc::Layout;
use loom::alloc::{alloc, dealloc};

use loom::sync::Arc;

use loom::sync::atomic::{AtomicUsize, fence};
use std::sync::atomic::Ordering;

use loom::sync::Condvar;
use loom::sync::Mutex;
use loom::thread;

use std::cell::RefCell;

fn main() {
    loom::model(|| {
        let causal_cell = CausalCell::new(42);
        unsafe { let _ = causal_cell.with_deferred(|x| *x + 1); }
        unsafe { let _ = causal_cell.with_deferred_mut(|x| *x + 2); }
        causal_cell.check();
        causal_cell.check_mut();

        println!("----------------------------------------------------------");

        // XXX: `alloc` doesn't use `Allocation::new()`, so only
        // `Allocation::drop` is printed.  Tried using `new` in `alloc`, but
        // it causes a panic for some reason.
        let layout = Layout::new::<i32>();
        unsafe {
            let ptr = alloc(layout);
            dealloc(ptr, layout);
        }

        println!("----------------------------------------------------------");

        let mut arc = Arc::new(7);
        let _ = arc.clone();
        Arc::get_mut(&mut arc);

        println!("----------------------------------------------------------");

        let mut atomic = AtomicUsize::new(80);
        let _ = atomic.load(Ordering::AcqRel);
        let _ = atomic.store(99, Ordering::Release);
        let _ = atomic.fetch_add(2, Ordering::SeqCst);
        AtomicUsize::get_mut(&mut atomic);
        fence(Ordering::Acquire);

        println!("----------------------------------------------------------");

        // From
        // https://doc.rust-lang.org/stable/std/sync/struct.Condvar.html
        let pair = Arc::new((Mutex::new(false), Condvar::new()));
        let pair2 = pair.clone();

        thread::spawn(move || {
            let (mutex, cvar) = &*pair2;
            let mut started = mutex.lock().unwrap();
            *started = true;
            cvar.notify_one();
            // cvar.notify_all();
        });

        let (mutex, cvar) = &*pair;
        let mut started = mutex.lock().unwrap();
        while !*started {
            started = cvar.wait(started).unwrap();
        }

        println!("----------------------------------------------------------");

        loom::thread::yield_now();

        println!("----------------------------------------------------------");

        let th1 = thread::spawn(|| {});
        let th2 = thread::spawn(|| {});

        th1.join().unwrap();
        th2.join().unwrap();

        println!("----------------------------------------------------------");

        // From
        // https://doc.rust-lang.org/stable/std/thread/struct.LocalKey.html
        loom::thread_local!(static FOO: RefCell<u32> = RefCell::new(1));

        FOO.with(|f| {
            assert_eq!(*f.borrow(), 1);
            *f.borrow_mut() = 2;
        });

        println!("----------------------------------------------------------");
    });
}

nkaretnikov · 2019-11-03T23:24:11Z

Let me know if you can think of a way to make this even more useful, or if you spot any issues!

nkaretnikov · 2019-11-03T23:36:14Z

One issue I'm aware of is that some messages are now printed a bit later.

Right after switching to tracing:

Nov 04 02:26:19.358 TRACE loom::rt: thread_done: set_terminated
Nov 04 02:26:19.358  INFO loom::rt::execution: ~~~~~~~~ THREAD 0 ~~~~~~~~

The most recent commit:

Nov 04 02:28:48.847  INFO loom::rt::execution: ~~~~~~~~ THREAD 0 ~~~~~~~~
Nov 04 02:28:48.848 TRACE loom::rt: thread_done: terminate thread=Id(1) switch=true

This happens because I moved some trace points a bit to be able to print more context.

I don't think it matters a lot, it's just something to be aware of. Just a heads up.

nkaretnikov · 2019-11-03T23:54:12Z

Another minor thing is that mutex is printed below as Mutex instead of Object (via mutex.obj) like everywhere else because the obj field is private. Decided not to change the field visibility since it's not a big deal, but I gathered I should mention this just in case.

trace!(obj = ?self.obj, mutex = ?mutex, "Condvar::wait");

hawkw

I left some comments on minor tracing style nits, which aren't blockers for merging this PR. Also, I had some thoughts on potentially using tracing's spans to include information about the iteration and thread in all the recorded events.

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...)

But, I think it would be fine to look into this in a follow-up PR or series of follow-ups; I think we should get some logging merged before we spend too much time on adding more detailed diagnostics.

src/cell/causal.rs

hawkw · 2019-11-04T16:52:27Z

src/model.rs

-                println!("");
+                info!("");
+                info!(" ================== Iteration {} ==================", i);
+                info!("");


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.

I think the header should be printed as is anyway at the info level (same for the thread one) because it's easier to read logs with it at the trace level. Also, at the info level this still provides
useful high-level information about the way threads/iterations are scheduled, without the overhead of trace messages.

As for using spans for iterations and threads, I'm all for it, but I think it should be done separately since (1) it requires some changes to pass spans around, (2) I don't know how much time I can spend on this PR, and (3) there's barely any logging in master now.

As for using spans for iterations and threads, I'm all for it, but I think it should be done separately since (1) it requires some changes to pass spans around, (2) I don't know how much time I can spend on this PR, and (3) there's barely any logging in master now.

I totally agree, this was intended as a suggestion for a future branch! Let's move forwards with this as-is and add spans afterwards.

src/rt/alloc.rs

src/rt/mutex.rs

src/rt/notify.rs

src/rt/object.rs

nkaretnikov · 2019-11-05T05:46:56Z

Excellent suggestions, going to address them now!

nkaretnikov · 2019-11-05T07:45:36Z

Okay, I think this is ready to be merged. Let me know if I missed something!

hawkw

This looks great to me! Let's go ahead and merge it (unless @carllerche has anything to add). We can add more diagnostics in subsequent PRs.

fiahil · 2021-09-14T08:16:47Z

Hello !

I'm using loom to check the validity of a library I'm developping, but I fail to see why a particular iteration trigger a bad state. This PR would help me A LOT, any chance that it will make it into master ?

Darksonn · 2021-09-14T11:18:56Z

Considering the number of merge conflicts, it would probably take some work.

fiahil · 2021-09-14T13:22:28Z

I took the liberty to fix most conflicts here : fiahil@c3e667c

Considering the differences between the two versions, a fresh review might be necessary !

Darksonn · 2021-09-14T13:27:23Z

You can open a new PR with your changes.

Darksonn · 2021-10-05T10:31:37Z

Merged in #227

nkaretnikov force-pushed the logging branch from 54ee81c to e9ba1a9 Compare October 29, 2019 16:55

nkaretnikov force-pushed the logging branch from e9ba1a9 to 1f8b71a Compare October 29, 2019 17:16

Improve logging

1f8b71a

hawkw reviewed Oct 29, 2019

View reviewed changes

nkaretnikov added 10 commits November 4, 2019 00:28

Use the tracing crate for logging

db5ec83

Print more information in rt::alloc

3438020

Print more information in rt::arc

89ca99c

Print more information in rt::atomic

02d842b

Print more information in rt::condvar

c8710a5

Print more information in rt::mod

b245280

Print more information in rt::mutex

b640a3c

Print more information in rt::notify

102fa9d

Print more information in rt::object

639ff2c

Fix formatting issues

f6ffb78

Move a trace point before a method call

2ec451e

hawkw reviewed Nov 4, 2019

View reviewed changes

nkaretnikov added 2 commits November 5, 2019 09:20

Use a simplified macro variant for locals

eb5b06c

Use more descriptive names

18bdd22

nkaretnikov force-pushed the logging branch from 697fbfc to 18bdd22 Compare November 5, 2019 07:39

hawkw approved these changes Nov 5, 2019

View reviewed changes

hawkw mentioned this pull request Nov 5, 2019

add tracing spans to loom diagnostics #95

Open

Merge branch 'master' into logging

9f252a5

fiahil mentioned this pull request Sep 14, 2021

Improve logging #2 #227

Merged

Darksonn closed this Oct 5, 2021

Improve logging #91

Improve logging #91

Conversation

nkaretnikov commented Oct 29, 2019

nkaretnikov commented Oct 29, 2019

nkaretnikov commented Oct 29, 2019

nkaretnikov commented Oct 29, 2019

hawkw commented Oct 29, 2019

hawkw commented Oct 29, 2019

hawkw left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

nkaretnikov commented Nov 2, 2019

nkaretnikov commented Nov 3, 2019

nkaretnikov commented Nov 3, 2019

nkaretnikov commented Nov 3, 2019

nkaretnikov commented Nov 3, 2019

hawkw left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

nkaretnikov commented Nov 5, 2019

nkaretnikov commented Nov 5, 2019

hawkw left a comment

Choose a reason for hiding this comment

fiahil commented Sep 14, 2021

Darksonn commented Sep 14, 2021

fiahil commented Sep 14, 2021

Darksonn commented Sep 14, 2021

Darksonn commented Oct 5, 2021