Why cyclicBarrier can't be acquired right after barrier action execution?

Question

Let's consider the following piece of code:

public static void main(String[] args) throws InterruptedException {
    CyclicBarrier cb = new CyclicBarrier(3, () -> {
        logger.info("Barrier action starting");
        try {
            Thread.sleep(5000);
        } catch (InterruptedException e) {
            e.printStackTrace();
        }
        logger.info("Barrier action finishing");
    });
    for (int i = 0; i < 6; i++) {
        int counter = i;
        Thread.sleep(100);
        new Thread(() -> {
            try {
                logger.info("Try to acquire barrier for {}", counter);
                cb.await();
                logger.info("barrier acquired for {}", counter);

            } catch (Exception e) {
                e.printStackTrace();
            }

        }).start();
    }
}

I've created barrier with size = 3 and barrirer action which takes 5 seconds.

I see following output:

2019-10-27 15:23:09.393  INFO   --- [       Thread-0] my.playground.RemoteServiceFacade        : Try to acquire barrier for 0
2019-10-27 15:23:09.492  INFO   --- [       Thread-1] my.playground.RemoteServiceFacade        : Try to acquire barrier for 1
2019-10-27 15:23:09.593  INFO   --- [       Thread-2] my.playground.RemoteServiceFacade        : Try to acquire barrier for 2
2019-10-27 15:23:09.594  INFO   --- [       Thread-2] my.playground.RemoteServiceFacade        : Barrier action starting
2019-10-27 15:23:09.693  INFO   --- [       Thread-3] my.playground.RemoteServiceFacade        : Try to acquire barrier for 3
2019-10-27 15:23:09.794  INFO   --- [       Thread-4] my.playground.RemoteServiceFacade        : Try to acquire barrier for 4
2019-10-27 15:23:09.897  INFO   --- [       Thread-5] my.playground.RemoteServiceFacade        : Try to acquire barrier for 5
2019-10-27 15:23:14.594  INFO   --- [       Thread-2] my.playground.RemoteServiceFacade        : Barrier action finishing
2019-10-27 15:23:14.595  INFO   --- [       Thread-2] my.playground.RemoteServiceFacade        : barrier acquired for 2
2019-10-27 15:23:14.595  INFO   --- [       Thread-5] my.playground.RemoteServiceFacade        : Barrier action starting
2019-10-27 15:23:19.596  INFO   --- [       Thread-5] my.playground.RemoteServiceFacade        : Barrier action finishing
2019-10-27 15:23:19.597  INFO   --- [       Thread-0] my.playground.RemoteServiceFacade        : barrier acquired for 0
2019-10-27 15:23:19.597  INFO   --- [       Thread-4] my.playground.RemoteServiceFacade        : barrier acquired for 4
2019-10-27 15:23:19.597  INFO   --- [       Thread-3] my.playground.RemoteServiceFacade        : barrier acquired for 3
2019-10-27 15:23:19.597  INFO   --- [       Thread-1] my.playground.RemoteServiceFacade        : barrier acquired for 1
2019-10-27 15:23:19.597  INFO   --- [       Thread-5] my.playground.RemoteServiceFacade        : barrier acquired for 5

So we can see that:

First barrier action lasts 15:23:09 - 15:23:14
Second barrier action lasts 15:23:14 - 15:23:19

But only one thread was able to log after first barrier action termination:

2019-10-27 15:23:14.595  INFO   --- [       Thread-2] my.playground.RemoteServiceFacade        : barrier acquired for 2

I expected 3 threads should be able to acquire approximately at 15:23:14 because CyclicBarrier size is 3.

Could you explain this behaviour?

P.S.

I tried to run this code a lot of time and always the similar result.

P.S.2.

I tried to change timings a bit:

public static void main(String[] args) throws InterruptedException {
    CyclicBarrier cb = new CyclicBarrier(3, () -> {
        logger.info("Barrier action starting");
        try {
            Thread.sleep(500);
        } catch (InterruptedException e) {
            e.printStackTrace();
        }
        logger.info("Barrier action finishing");
    });
    for (int i = 0; i < 6; i++) {
        int counter = i;
        Thread.sleep(1000);
        new Thread(() -> {
            try {
                logger.info("Try to acquire barrier for {}", counter);
                cb.await();
                logger.info("barrier acquired for {}", counter);

            } catch (Exception e) {
                e.printStackTrace();
            }

        }).start();
    }
}

And I see expected results:

2019-10-27 23:22:14.497  INFO   --- [       Thread-0] my.playground.RemoteServiceFacade        : Try to acquire barrier for 0
2019-10-27 23:22:15.495  INFO   --- [       Thread-1] my.playground.RemoteServiceFacade        : Try to acquire barrier for 1
2019-10-27 23:22:16.495  INFO   --- [       Thread-2] my.playground.RemoteServiceFacade        : Try to acquire barrier for 2
2019-10-27 23:22:16.496  INFO   --- [       Thread-2] my.playground.RemoteServiceFacade        : Barrier action starting
2019-10-27 23:22:16.998  INFO   --- [       Thread-2] my.playground.RemoteServiceFacade        : Barrier action finishing
2019-10-27 23:22:16.998  INFO   --- [       Thread-0] my.playground.RemoteServiceFacade        : barrier acquired for 0
2019-10-27 23:22:16.998  INFO   --- [       Thread-2] my.playground.RemoteServiceFacade        : barrier acquired for 2
2019-10-27 23:22:16.998  INFO   --- [       Thread-1] my.playground.RemoteServiceFacade        : barrier acquired for 1
2019-10-27 23:22:17.495  INFO   --- [       Thread-3] my.playground.RemoteServiceFacade        : Try to acquire barrier for 3
2019-10-27 23:22:18.495  INFO   --- [       Thread-4] my.playground.RemoteServiceFacade        : Try to acquire barrier for 4
2019-10-27 23:22:19.496  INFO   --- [       Thread-5] my.playground.RemoteServiceFacade        : Try to acquire barrier for 5
2019-10-27 23:22:19.499  INFO   --- [       Thread-5] my.playground.RemoteServiceFacade        : Barrier action starting
2019-10-27 23:22:20.002  INFO   --- [       Thread-5] my.playground.RemoteServiceFacade        : Barrier action finishing
2019-10-27 23:22:20.003  INFO   --- [       Thread-5] my.playground.RemoteServiceFacade        : barrier acquired for 5
2019-10-27 23:22:20.003  INFO   --- [       Thread-3] my.playground.RemoteServiceFacade        : barrier acquired for 3
2019-10-27 23:22:20.003  INFO   --- [       Thread-4] my.playground.RemoteServiceFacade        : barrier acquired for 4

score 1 · Accepted Answer · answered Oct 27 '19 at 13:24

A fascinating question, it's not super trivial but I'll try to explain it as succinctly as I can.

Although multithreading doesn't guarantee any type of execution order, for this answer let's imagine there are two sequences that happen first:

All threads start at exactly the same time
All threads invoke barrier.await() at the same time.

In this case you'd see an output like

Try to acquire barrier for 0
Try to acquire barrier for 1
Try to acquire barrier for 2
Try to acquire barrier for 3
Try to acquire barrier for 4
Try to acquire barrier for 5

The current state of your 6 threads are as follows:

Threads 0 and 1 await on a shared Condition since three threads have not reached the barrier "yet"
Thread 2 is still runnable as the "tripping" thread for the barrier
Threads 3, 4 and 5 will wait on a lock.lock invocation of the barrier (the same Lock instance in which the Condition was created.

When the barrier sees thread 2 it previously recorded 0 and 1 as reaching the barrier so it knows that this cycle is completed and will release 0 and 1. But before it releases the other two threads, it needs to run the barrierAction you define as sleeping for 5 seconds, so it does that.

You'd then see output

Barrier action starting
Barrier action finishing

Thread 2 still holds the lock, is RUNNABLE and is ready to exit the barrier, so it does that and you see this output.

barrier acquired for 2

But before thread 2 exists, it will signal all other threads waiting on the current barrier. Here is where it gets tricky, the await by 0 and 1 is done on the shared Condition. The Condition is shared across all barrier "generations". So even though the first two threads were awaiting prior to the second 3 threads locking, when a signalAll is done, the first generation threads still have to wait their turn to wake up.

At this point we have 5 threads in a BLOCKED (3, 4 & 5) or TIMED_WAITING (0, 1) state. In this example the timing is important of when they block/wait on the Lock. If they all happen in order the queue for the critical section would be:

Thread-0 -> Thread-1 -> Thread-5 -> Thread-4 -> Thread-3 
   |                                               |
  TAIL                                            HEAD

So that the next threads released will be Thread-3, then 4 and subsequently 5. The reason the queue looks like this is because all threads reach the lock at the same time and they all queue up, thread 0 and 1 obviously reached it first and so make it into the barrier's critical section, but then await while thread 2 comes in to wake them up, but now 0 and 1 get placed on the end of the queue and 3, 4 and 5 will be triggered next.

When thread 2 leaves the barrier and signalAll threads 3 and 4 will run and since they are part of the second generation will suspend until thread 5 comes through and triggers the barrier action. This then prints out

Barrier action starting
Barrier action finishing

Finally, thread 5 will signalAll again and the rest of the threads will wake up complete.

In this case you will see thread 5 first complete and the rest to follow

barrier acquired for 5
barrier acquired for 0
barrier acquired for 1
barrier acquired for 3
barrier acquired for 4

Oh, it is a bit complex. As I understood(see my update) that reason of this unexpected behaviour that some threads comes during the barrier action — gstackoverflow, Oct 27 '19 at 20:27
@gstackoverflow Yes, by slowing down the threads, you let the first generation (threads 0, 1 and 2) to approach and exit the barrier before the second generation (3, 4, 5) threads get queued up on the `Lock`. — John Vint, Oct 28 '19 at 10:26
So if at least one thread is coming during barrier action - it means that all minus 1 threads waiting for lock will wait one more iteration for unlock. I am not sure if it is correct behaviour — gstackoverflow, Oct 28 '19 at 10:36
I agree the behavior is slightly surprising. `it means that all minus 1 threads waiting for lock will wait one more iteration for unlock` That's right, technically they are all unlocking but must wait for the 2nd generation threads to reach the barrier before the 1st generation threads can exit. — John Vint, Oct 28 '19 at 11:16
@gstackoverflow This type of behavior is actually resolved using the [Phaser](https://docs.oracle.com/javase/9/docs/api/java/util/concurrent/Phaser.html). You tell the `Phaser` "I want to wait on _this_ particular phase (generation). One phase of threads will not be affected by another phase of threads. It also supports parent and child phases/generations but that's not too important for this question. — John Vint, Oct 28 '19 at 11:16
it might be helpful for my REAL task. Thanks for hint. Actually I want to be able to run barrier actions in parallel. So I want to collect 3 elements from different threads and invoke only one expensive batch call and then route correct response to correct thread. — gstackoverflow, Oct 28 '19 at 11:26
Got it. With the `Phaser` the "barrier action" is implemented by overriding the `onAdvance` method. — John Vint, Oct 28 '19 at 11:30
Last comment on the `CyclicBarrier`, but I believe the general use-case this class is to have the `number of parties == number of threads`. I don't see it explicitly documented but the underlying implementation seems to imply it. — John Vint, Oct 28 '19 at 11:36

Why cyclicBarrier can't be acquired right after barrier action execution?

1 Answers1