Unexpected event delivery order in AsyncEventBus

[christo...@gmail.com]

Hallo,
I am currently experimenting with AsyncEventBus and I am facing an unexpected event order that I do not understand. With respect to the docs, I thought that events are delivered in exact the order in which they were posted:

Have a look to the following code:

public class Test {

    private static AsyncEventBus eventBus = new AsyncEventBus(Executors.newFixedThreadPool(10));
   
    public static void main(String[] args) throws Exception {
        eventBus.register(new EventListener());
        eventBus.register(new SlowEventListener());
        eventBus.register(new EventListener());
        eventBus.post("E1: " + Instant.now());
        eventBus.post("E2: " + Instant.now());
    }
   
    public static class EventListener {
       
        @Subscribe
        public void changeOccurred(Object event) {
            System.out.println(Thread.currentThread() + "- " + this +": " + event);
        }
       
    }
   
    public static class SlowEventListener {
       
        @Subscribe
        public void changeOccurred(Object event) throws Exception {
            System.out.println(Thread.currentThread() + "- " + this +": " + event);
            Thread.sleep(2000);
            eventBus.post("E INTERNAL: " + Instant.now());
        }
       
    }
}

I get the following output:

Thread[pool-1-thread-3,5,main]- test.Test$EventListener@59f95c5d: E1: 2017-04-19T10:39:05.254Z
Thread[pool-1-thread-2,5,main]- test.Test$SlowEventListener@48cf768c: E1: 2017-04-19T10:39:05.254Z
Thread[pool-1-thread-6,5,main]- test.Test$EventListener@59f95c5d: E2: 2017-04-19T10:39:05.329Z
Thread[pool-1-thread-1,5,main]- test.Test$EventListener@39ed3c8d: E1: 2017-04-19T10:39:05.254Z
Thread[pool-1-thread-4,5,main]- test.Test$EventListener@39ed3c8d: E2: 2017-04-19T10:39:05.329Z
Thread[pool-1-thread-7,5,main]- test.Test$EventListener@39ed3c8d: E INTERNAL: 2017-04-19T10:39:07.330Z
Thread[pool-1-thread-8,5,main]- test.Test$SlowEventListener@48cf768c: E INTERNAL: 2017-04-19T10:39:07.330Z
Thread[pool-1-thread-9,5,main]- test.Test$EventListener@59f95c5d: E INTERNAL: 2017-04-19T10:39:07.330Z
Thread[pool-1-thread-10,5,main]- test.Test$EventListener@39ed3c8d: E INTERNAL: 2017-04-19T10:39:09.331Z
Thread[pool-1-thread-3,5,main]- test.Test$EventListener@59f95c5d: E INTERNAL: 2017-04-19T10:39:09.331Z
Thread[pool-1-thread-5,5,main]- test.Test$SlowEventListener@48cf768c: E2: 2017-04-19T10:39:05.329Z

Interesting is:
Thread[pool-1-thread-2,5,main]- test.Test$SlowEventListener@48cf768c: E1: 2017-04-19T10:39:05.254Z
Thread[pool-1-thread-8,5,main]- test.Test$SlowEventListener@48cf768c: E INTERNAL: 2017-04-19T10:39:07.330Z
Thread[pool-1-thread-5,5,main]- test.Test$SlowEventListener@48cf768c: E2: 2017-04-19T10:39:05.329Z

The event delivery order is not the same as the event posting order. I would expect that E INTERNAL: 2017-04-19T10:39:07.330Z comes after E2: 2017-04-19T10:39:05.329Z.

This output confuses me. Can someone help? What's going on here?

Regards,
Christoph

[Johan Van den Neste]

It's async. You send 2 events to 3 listeners. No guarantees can be made in the order of reception of those 2 event 'chains' with regard to each other.

So the order of reception of any event in the E1 'chain' is irrelevant to events from the E2 'chain'.

"48cf768c: E INTERNAL: 2017-04-19T10:39:07.330Z" is in the E1 event chain and thus unrelated in timing and order to the E2 events. It would be helpful to log the event 'heritage'. In the following example derived from yours, events of the same character should be ordered in length. e.g. AA cannot appear after AAA

private static AsyncEventBus eventBus = new AsyncEventBus(Executors.newFixedThreadPool(10));

public interface Listener {

  @Subscribe void receive(final Object event) throws Exception;

}

public static void print(final String listener, final Object event) {

  System.out.println(event + " " + listener);

}

public static void main(final String[] args) throws Exception {

  eventBus.register((Listener) event -> print("L1", event));

  eventBus.register((Listener) event -> print("L2", event));

  eventBus.register((Listener) event -> {

    print("L3", event);

    Thread.sleep(2000);

    eventBus.post(event + "" + event.toString().charAt(0));

  });

  eventBus.post("A");

  eventBus.post("B");

}

--
guava-...@googlegroups.com
Project site: https://github.com/google/guava
This group: http://groups.google.com/group/guava-discuss
 
This list is for general discussion.
To report an issue: https://github.com/google/guava/issues/new
To get help: http://stackoverflow.com/questions/ask?tags=guava
---
You received this message because you are subscribed to the Google Groups "guava-discuss" group.
To unsubscribe from this group and stop receiving emails from it, send an email to guava-discus...@googlegroups.com.
To view this discussion on the web visit https://groups.google.com/d/msgid/guava-discuss/d5270d0d-7115-4c5d-908a-c29be7deda50%40googlegroups.com.
For more options, visit https://groups.google.com/d/optout.

[christo...@gmail.com]

Thank you very much for your example.

Well, I think it is possible to ensure that subsequent event posts in time are delivered subsequently, but this is not the way AsyncEventBus works in case of multi-threading. It would be nice to have, that hint in the docs.

[Ben Manes]

In that case you would need a mailbox to queue the messages per subscriber, e.g. using an actor library like Akka.

[Johan Van den Neste]

I should probably point out that what I said cannot even be guaranteed between the listeners and is only valid for any for L3

so you might still get something like (unlikely in the example, but if you drive up the numbers and resource contention then bingo)

AAA L3

AA L2

but never

AAAA L2

AAA L3

It just illustrates how annoyingly difficult it is to think about time :)

That said, I'm not very familiar with the design of EventBus, so it is possible that it actually guarantees more than I would assume.