Consider using a dynamic pool or increasing the default pool size

[forbushbl]

When I create a DefaultConnectionContext with no size specified, it appears that the default configuration creates a pool matching the number of CPUs on your system. (see _DefaultConnectionContext.java and PoolResources.java)

This may work well on a machine with multiple CPUs but we are running this as a BOSH errand where the errand VM is configured to have only 1 CPU. So when we try to do multiple operations in parallel, it appears that if one of the operations takes longer than 45 seconds, then the second operation fails with the exception below.

reactor.core.Exceptions$ReactiveException: java.util.concurrent.TimeoutException: Acquire operation took longer then configured maximum time
  at reactor.core.Exceptions.propagate(Exceptions.java:218)
  at reactor.core.publisher.BlockingSingleSubscriber.blockingGet(BlockingSingleSubscriber.java:117)
  at reactor.core.publisher.Mono.blockMillis(Mono.java:1215)
  at reactor.core.publisher.Mono.block(Mono.java:1193)
  at org.lds.cloudfoundry.configurer.controller.ApplicationController.createApplication(ApplicationController.java:91)
  at org.lds.cloudfoundry.configurer.handler.DeploymentStepHandler.createDeployment(DeploymentStepHandler.java:81)
  at org.lds.cloudfoundry.configurer.handler.DeploymentStepHandler.handleStep(DeploymentStepHandler.java:50)
  at org.lds.cloudfoundry.configurer.controller.MainController.configureCloud(MainController.java:32)
  at org.lds.cloudfoundry.configurer.Main$ApplicationStartup.run(Main.java:64)
  at org.springframework.boot.SpringApplication.callRunner(SpringApplication.java:791)
  ... 11 common frames omitted
Caused by: java.util.concurrent.TimeoutException: Acquire operation took longer then configured maximum time
at io.netty.channel.pool.FixedChannelPool.<init>(...)(Unknown Source)

Here is the line where I'm seeing this exception thrown.

cf.applications().start(StartApplicationRequest.builder().name(application.getName()).build()).block();

Here is the line in context with the logging that is happening in parallel. Basically we connect to logging so that log messages from the application will be printed to the console, then we start the application and wait for it to finish. When it is finished, we dispose of the logging.

Disposable logDisposable = null;
try {
    LOG.info("Starting application logging: " + application.getName());
    LogsRequest logsRequest = LogsRequest.builder().name(application.getName()).build();
    logDisposable = cf.applications().logs(logsRequest).subscribe(consumer -> {
        if (consumer.getMessageType() == MessageType.ERR) {
            LOG.error("\t" + application.getName() + "\t\t| " + consumer.getMessage());
        } else {
            LOG.info("\t" + application.getName() + "\t\t| " + consumer.getMessage());
        }
    });

    LOG.info("Starting application: " + application.getName());
    cf.applications().start(StartApplicationRequest.builder().name(application.getName()).build()).block();
} finally {
    if (logDisposable != null) {
        LOG.info("Stopping application logging: " + application.getName());
        logDisposable.dispose();
    }
}

It seems like 45 seconds is the default timeout for acquiring a channel from the pool (see PoolResources.java) and in this case, it takes longer than 45 seconds for the application to start.

When I set the connection pool size > 1 then the issue is resolved

@Bean
public DefaultConnectionContext context(CloudConfigurationPlan cloudConfigurationPlan) {
  return DefaultConnectionContext.builder()
      .apiHost(cloudConfigurationPlan.getApi())
      .connectionPoolSize(2)
      .build();
}

Is there something I'm doing wrong here? If not, I recommend either using an elastic pool or changing the default so that it has a sensible minimum (maybe 2?).

[cf-gitbot]

We have created an issue in Pivotal Tracker to manage this:

https://www.pivotaltracker.com/story/show/137063261

The labels on this github issue will be updated when the story is started.

[forbushbl]

By the way, this issue was introduced in v2.1.0 and seems to be related to changes introduced in reactor-netty v0.6.0.

[nebhale]

In general, I'd say that this working as designed today. Our choice to limit the number of connections in the pool was due to an unfortunate circumstance, where someone was opening 15K unique connections per minute to Pivotal Web Services. While this was an impressive feat, we realized that connections needed to be limited. The current pool size is possibly a bit too aggressive, and we'll revisit it for the next release. In the mean time, the connectionPoolSize() is exposed exactly for this reason, so I'd encourage you to use it until we address this issue for you.

[forbushbl]

I agree, 15K connections probably doesn't make much sense. :) connectionPoolSize() will work great for us. It was fairly tricky to figure out what the "Acquire operation took longer then configured maximum time" exception was all about and I thought I would share what I learned in case someone else runs into this. Not sure if this was the best forum. Also, I'm not sure if implementing a minimum default connection pool size of 2 might mitigate the issue altogether. Either way, we're in a good spot.

[nebhale]

@forbushbl I've been discussing this issue with @smaldini (lead of Reactor) this morning and we both agree that the current default is a bit too aggressive. I'm doing to make a tactical update to 2 x threads which will solve your issue, but we're going to do some deeper investigation about smarter strategies as well.

[forbushbl]

@nebhale I think the 2 x fix will work great for my scenario.