Multi-threaded traces with Deja vu

This post is part of a series about the framework Deja vu.

As previously argued bug fixing can be hard when left only with a stack trace. If you feel an agreement with me on that for a single-threaded case, you must feel it even stronger when it comes to a multi-threaded scenario! It is just inherently hard to reason about concurrent code.

Let’s see what Deja vu can do in a concurrent scenario.

Anatomy of a trace

All traces are initiated when methods annotated @Traced are called and a trace instance is built as the @Traced method executes. Most importantly the trace has an impure list which holds the result values of calls to @Impure methods. In a trace execution all such results are simply appended to this list. And in a re-run the framework sequentially replaces @Impure method calls with values of this list.

The guarantee Deja vu provides is that the absolute order of impure values is preserved from trace to re-run (absolute meaning all threads involved in executing a trace synchronizes when an impure value is “calculated”). By synchronizing on the trace instance when @Impure methods are called, only one @Impure method per trace executes at a time. To be able to re-run the trace with the same ordering of the impure values additional information is needed. Internally the impure list also holds the Deja vu thread id of the thread executing the method. In a re-run when impure values are requested Deja vu will run a predicate function: Deja vu thread id of the next impure value equals Deja vu thread id of the requesting thread. When this predicate fails the requesting thread is told to .wait(), and when the predicate succeeds the next impure value is returned and .notifyAll() is called. Note that this waiting and notifying only happens during re-run.

Attach thread

To meet the guarantee of Deja vu of preserving the absolute order of impure values, threading must be done in accordance with the framework. For a thread to be attached to a trace, Deja vu must assign it a thread id and the thread must be aware of the trace it belongs to.

The method annotation @AttachThread informs the framework that the method will initiate processing on another thread and this thread must be included in the trace. It only works by passing java.lang.Runnable instances as arguments to @AttachThread methods. The following code shows examples of this:

private ExecutorService executorService = //initialize

@AttachThread
private void runInThreadPool( Runnable runnable ) {
    executorService.submit(runnable);
}

@AttachThread
private void runInNewThread( Runnable runnable, Runnable another ) {
    new Thread( runnable ).start();
    execurotService.submit( another );
}

Example

Lets look at a complete example of a trace having some randomization and threading. First off is the Runnable implementation:

public class Runner implements Runnable {

    public void run() {
        uuid();
        try {
            Thread.sleep(randomLong());
        } catch (InterruptedException e) {
            e.printStackTrace();
        }
        uuid();
    }

    @Impure
    public String uuid() {
        return UUID.randomUUID().toString();
    }

    @Impure
    public Long randomLong() {
        return Long.valueOf(new Random().nextInt(1000));
    }
}

There are two impure methods: randomLong used to let the thread sleep making sure thread execution order gets mixed up, and uuid producing a random UUID string.

The initiater of the trace and threads is the following:

public class WithThreads {

    @Traced
    public void begin( Integer threads) {
        ExecutorService executorService = Executors.newCachedThreadPool();
        for ( int i=0; i<threads; i++ ) {
            runInThreadPool(executorService, new Runner());
        }
    }

    @AttachThread
    private void runInThreadPool( ExecutorService es, Runnable runnable ) {
        es.submit(runnable);
    }
}

For the purpose of traceability I added log statements when a new value was added to a trace and during re-run when values were read. Running and re-running the example with thread count set to 3 gave the following result:

225 [pool-1-thread-1] INFO [...] Traced value: 72a11c10-fd39-45f7-af0e-b16671fae05d
225 [pool-1-thread-3] INFO [...] Traced value: 6dc2181b-065c-4099-b6e7-0bd04e791229
226 [pool-1-thread-3] INFO [...] Traced value: 733
226 [pool-1-thread-2] INFO [...] Traced value: 676c13a5-1c34-401c-8a53-538d2ed1dd08
227 [pool-1-thread-2] INFO [...] Traced value: 323
228 [pool-1-thread-1] INFO [...] Traced value: 332
550 [pool-1-thread-2] INFO [...] Traced value: 9e5fb47d-a317-49e0-8aff-6d3fa34eba8d
561 [pool-1-thread-1] INFO [...] Traced value: dbf7958a-60b3-4f24-b99a-c5b193f8d05c
960 [pool-1-thread-3] INFO [...] Traced value: ff728ef9-6cf4-4e17-8014-c6b6d229a8ea
1220 [main] INFO [...] - Deja Vu run:
1227 [pool-2-thread-1] INFO [...] Read value: 72a11c10-fd39-45f7-af0e-b16671fae05d
1229 [pool-2-thread-2] INFO [...] Read value: 6dc2181b-065c-4099-b6e7-0bd04e791229
1230 [pool-2-thread-2] INFO [...] Read value: 733
1231 [pool-2-thread-3] INFO [...] Read value: 676c13a5-1c34-401c-8a53-538d2ed1dd08
1232 [pool-2-thread-3] INFO [...] Read value: 323
1233 [pool-2-thread-1] INFO [...] Read value: 332
1556 [pool-2-thread-3] INFO [...] Read value: 9e5fb47d-a317-49e0-8aff-6d3fa34eba8d
1566 [pool-2-thread-1] INFO [...] Read value: dbf7958a-60b3-4f24-b99a-c5b193f8d05c
1964 [pool-2-thread-2] INFO [...] Read value: ff728ef9-6cf4-4e17-8014-c6b6d229a8ea

By eyeballing the output it is easy to see that all impure values are read in the same order for both runs. Further inspection reveals the thread ids are handled correctly by Deja vu: for instance the thread named “pool-1-thread-3” has a corresponding thread in the re-run called “pool-2-thread-2” which outputs the same values and in the same order for the original run and in the re-run:

Real run:
225 [pool-1-thread-3] INFO [...] Traced value: 6dc2181b-065c-4099-b6e7-0bd04e791229
226 [pool-1-thread-3] INFO [...] Traced value: 733
960 [pool-1-thread-3] INFO [...] Traced value: ff728ef9-6cf4-4e17-8014-c6b6d229a8ea

Deja vu:
1229 [pool-2-thread-2] INFO [...] Read value: 6dc2181b-065c-4099-b6e7-0bd04e791229
1230 [pool-2-thread-2] INFO [...] Read value: 733
1964 [pool-2-thread-2] INFO [...] Read value: ff728ef9-6cf4-4e17-8014-c6b6d229a8ea

Summary

By using the @AttachThread annotation Deja vu allows for traceability and re-run of multi-threaded scenarios. Hopefully this gives an easier handling of concurrency bugs, because the trace can be replayed over and over again producing the bug.

Leave a Reply