Performance difference between RabbitTemplate's waitForConfirms and blocking correlation data callback

Viewed 506

I am implementing a service that needs to publish messages to a RabbitMQ broker in a reliable and blocking way. As described in https://www.rabbitmq.com/tutorials/tutorial-seven-java.html, there are multiple options for publisher confirmation. The most basic option is to use waitForConfirms. I tested the following code (with setting cachingConnectionFactory.setPublisherConfirmType(CachingConnectionFactory.ConfirmType.SIMPLE)) and it took about 100 seconds to publish 10,000 of these messages:

rabbitTemplate.invoke(rabbitOperations -> {
  rabbitOperations.convertAndSend("test_exchange", "test_key", "test message");
  return rabbitOperations.waitForConfirms(1000);
});

I also tested the asynchronous option (with setting cachingConnectionFactory.setPublisherConfirmType(CachingConnectionFactory.ConfirmType.CORRELATED)) with a very primitive blocking wrapper. The following code took about 20 seconds to publish 10,000 messages:

CountDownLatch latch = new CountDownLatch(1);
CorrelationData correlationData = new CorrelationData();
rabbitTemplate.convertAndSend("test_exchange", "test_key", "test message", correlationData);
correlationData.getFuture().addCallback(success -> {
  latch.countDown();
}, failure -> {
  latch.countDown();
});
latch.await();

As far as I understand the following quote in the above link, my first example should basically do the same that my second example does.

Think of waitForConfirmsOrDie as a synchronous helper which relies on asynchronous notifications under the hood.

But the performance difference is too massive for my assumption to be true. I see that RabbitTemplate.invoke executes a lot more stuff than my second code example. But what exactly is the reason for this massive performance difference? Is my second example bad practice, or is my first example in some unnecessary way inefficient?

EDIT Copy-pasting the code from Gary, I experienced the following:

StopWatch '': running time = 106379462700 ns
---------------------------------------------
ns         %     Task name
---------------------------------------------
17546479900  016 %  correlated
88832982800  084 %  simple

I am using Windows 10 Pro, RabbitMQ 3.8.9 running via docker run -it --rm --name rabbitmq -p 5672:5672 -p 15672:15672 rabbitmq:3-management, and Spring Boot 2.3.1

EDIT 2 Adding RabbitUtils.isPhysicalCloseRequired() to the simple confirmation code of Gary:

simpleTemplate.invoke(ops -> {
  ops.convertAndSend("so64857773", "test message");
  RabbitUtils.isPhysicalCloseRequired();
  return ops.waitForConfirms(1000);
});

yields the following results:

StopWatch '': running time = 46090067400 ns
---------------------------------------------
ns         %     Task name
---------------------------------------------
21100935900  046 %  correlated
24989131500  054 %  simple

It seems that when running a dockerized version of RabbitMQ on Windows, closing and recreating a channel is quite expensive.

EDIT 3 Using a native Windows 10 RabbitMQ server (3.8.9) with Erlang 23.1.3, performance massively increased. Using 10k messages, the correlated confirm test took only around 3 seconds. I increased the number of messages for the following two tests to 50k.

First test, with the original code from Gary:

StopWatch '': running time = 144403128200 ns
---------------------------------------------
ns         %     Task name
---------------------------------------------
19750222900  014 %  correlated
124652905300  086 %  simple

Second test, with RabbitUtils.isPhysicalCloseRequired() added as described in EDIT 2:

StopWatch '': running time = 30030523500 ns
---------------------------------------------
ns         %     Task name
---------------------------------------------
14549132300  048 %  correlated
15481391200  052 %  simple

Closing and reopening a channel seems to be very expensive on Windows - it does not seem to be a problem with using the dockerized version.

1 Answers

There is a lot more code involved with correlated confirms, so I would have expected that version to take more time (although not a huge difference).

I am not sure why you are seeing the behavior you observe.

However, in both cases, it's better to send multiple requests before waiting for the confirms; sending and waiting for each one will be significantly slower.

With correlated confirms, you can save off the CorrelationData instances and wait for the futures later.

EDIT

I am not seeing the same behavior as you; I get nearly identical performance using both methods; about 62 seconds in each case.

@SpringBootApplication
public class So64857773Application {

    public static void main(String[] args) {
        SpringApplication.run(So64857773Application.class, args);
    }

//  @Bean
//  Queue queue() {
//      return new Queue("so64857773");
//  }

    @Bean
    ApplicationRunner runner(CachingConnectionFactory cf, RabbitTemplate template) {
        return args -> {
            StopWatch watch = new StopWatch();
            cf.createConnection().close();
            watch.start("correlated");
            for (int i = 0; i < 10_000; i++) {
                CorrelationData cd = new CorrelationData();
                template.convertAndSend("", "so64857773", "test message", cd);
                cd.getFuture().get(1, TimeUnit.SECONDS);
            };
            watch.stop();

            cf.resetConnection();
            cf.setPublisherConfirmType(ConfirmType.SIMPLE);
            RabbitTemplate simpleTemplate = new RabbitTemplate(cf);
            cf.createConnection().close();
            watch.start("simple");
            for (int i = 0; i < 10_000; i++) {
                simpleTemplate.invoke(ops -> {
                    ops.convertAndSend("so64857773", "test message");
                    return ops.waitForConfirms(1000);
                });
            };
            watch.stop();

            System.out.println(watch.prettyPrint());
        };
    }

}
spring.rabbitmq.publisher-confirm-type=correlated

Result:

StopWatch '': running time = 124245233864 ns
---------------------------------------------
ns         %     Task name
---------------------------------------------
62136894432  050%  correlated
62108339432  050%  simple
Related