Environment creation is taking too much time

Java SDK
1

We are creating environment variable like this.

    logger.info(marker, "Couchbase## initializeBuckets tracerConfig start time {}", LocalDateTime.now());

    ThresholdLoggingTracerConfig.Builder tracer = ThresholdLoggingTracerConfig.builder()
            .emitInterval(Duration.ofMillis(tracerConfig.getLong("emitInterval", 20000L)))
            .kvThreshold(Duration.ofMillis(tracerConfig.getLong("kvThreshold", 20000L)))
            .queryThreshold(Duration.ofMillis(tracerConfig.getLong("n1qlThreshold", 60000L)))
            .sampleSize(tracerConfig.getInteger("sampleSize", 5)).searchThreshold(Duration.ofSeconds(60));

    logger.info(marker, "Couchbase## initializeBuckets before environment time {}", LocalDateTime.now());

    environment = ClusterEnvironment.builder()
        .thresholdLoggingTracerConfig(tracer)
        .retryStrategy(BestEffortRetryStrategy.INSTANCE)
        .ioConfig(IoConfig.enableDnsSrv(false))
        .timeoutConfig(TimeoutConfig.connectTimeout(Duration.ofMillis(
                couchbaseConfig.getLong(CONNECT_TIMEOUT, CONNECT_TIMEOUT_DEFAULT_VALUE)))
            .queryTimeout(Duration.ofMillis(couchbaseConfig.
                getLong(QUERY_TIMEOUT, QUERY_TIMEOUT_DEFAULT_VALUE)))
            .kvTimeout(Duration.ofMillis(couchbaseConfig.getLong(KV_TIMEOUT, KV_TIMEOUT_DEFAULT_VALUE))))
        .build();

    logger.info(marker, "Couchbase## initializeBuckets after environment time {}", LocalDateTime.now());

It takes around 6-8 seconds to crate environment variable. Even if we remove thresholdLoggingTracerConfig or use just below code to create default environment, it remains same.

environment = ClusterEnvironment.builder()

Is any better way to optimize this creation and also can you please help me to understand why it takes this much time to create environment.

2

Hi @amitsinha

ClusterEnvironment creation should be instant, as should Cluster.connect: neither is doing any real synchronous IO work. We’ve not seen any such issues in our testing or had any user reports on it either.

I’d suggest attaching a profiler and seeing where the sticking point is.

3

If you can send a kill -3 while it is executing will give a thread dump and be able to see a little bit what it is doing.

environment = ClusterEnvironment.builder()

There is really nothing to that. All that needs to happen is that the classes get loaded. And 6-8 seconds is really, really long for that. I get 152 ms.

long t0=System.currentTimeMillis();
ClusterEnvironment.Builder env = ClusterEnvironment.builder();
System.err.print("et: "+(System.currentTimeMillis()-t0));

et: 152

In your original sample there are tracerConfig.getLong() and couchbaseConfig.getLong() calls which are not couchbase. You might want to investigate what they do.

1 Like
4

thanks for in detail information.

6

On my local dev machine, Couchbase startup used to be slow because of Log4J2 initialization until I addressed this issue: java - log4j (2.20.0) takes several seconds to initialize - Stack Overflow

What worked for me was adding these lines to my /etc/hosts file:

127.0.0.1       XVVVK6G61F.local
::1             XVVVK6G61F.local

where XVVVK6G61F.local is the name of my machine as stored in the HOST environment vairable:

> echo $HOST
XVVVK6G61F.local
7

correct David, log4j had issue… but we are using slf4j and i am not aware of any such issue in slf4j

8

SLF4J is a logging facade that routes logging requests to a specific logger implementation (like logback, logj42, etc.). Which SLF4J binding are you using?

9

If you want to time what ClusterEnvironment.builder() does :


      long t0;
      t0 = System.nanoTime();
      IoEnvironment.Builder ioEnvironment = IoEnvironment.builder();
      System.out.println("IOEnvironmnent: " + (System.nanoTime() - t0)+" ns");
      t0 = System.nanoTime();
      IoConfig.Builder ioConfig = IoConfig.builder();
      System.out.println("IoConfig: " + (System.nanoTime() - t0)+" ns");
      t0 = System.nanoTime();
      CompressionConfig.Builder compressionConfig = CompressionConfig.builder();
      System.out.println("CompressionConfig: " + (System.nanoTime() - t0)+" ns");
      t0 = System.nanoTime();
      SecurityConfig.Builder securityConfig = SecurityConfig.builder();
      System.out.println("SecurityConfig: " + (System.nanoTime() - t0)+" ns");
      t0 = System.nanoTime();
      TimeoutConfig.Builder timeoutConfig = TimeoutConfig.builder();
      System.out.println("TimeoutConfig: " + (System.nanoTime() - t0)+" ns");
      t0 = System.nanoTime();
      LoggerConfig.Builder loggerConfig = LoggerConfig.builder();
      System.out.println("LoggerConfig: " + (System.nanoTime() - t0)+" ns");
      t0 = System.nanoTime();
      OrphanReporterConfig.Builder orphanReporterConfig = OrphanReporterConfig.builder();
      System.out.println("OrphanReporterConfig: " + (System.nanoTime() - t0)+" ns");
      t0 = System.nanoTime();
      ThresholdLoggingTracerConfig.Builder thresholdLoggingTracerConfig = ThresholdLoggingTracerConfig.builder();
      System.out.println("ThresholdLoggingTracerConfig: " + (System.nanoTime() - t0)+" ns");
      t0 = System.nanoTime();
      LoggingMeterConfig.Builder loggingMeterConfig = LoggingMeterConfig.builder();
      System.out.println("LoggingMeterConfig: " + (System.nanoTime() - t0)+" ns");

IOEnvironmnent: 4256376 ns
IoConfig: 9375298 ns
CompressionConfig: 855580 ns
SecurityConfig: 1006876 ns
TimeoutConfig: 1109771 ns
LoggerConfig: 3007742 ns
OrphanReporterConfig: 1743037 ns
ThresholdLoggingTracerConfig: 1988468 ns
LoggingMeterConfig: 1621098 ns
10

I Agree with this but our logger is intialized much before this method and when we evaluate logs, exactly those 2 logs before and after is taking time… rest all logs are ok… there are 15-20 logs before creation of environment. All are ok and on time.
I am yet to run profiler.

11

You can just run the code I provided and you will likely have your answer.

And if the delay is from some initialization outside of Couchbase - creating the environment a second time should not have that delay.

12

This topic was automatically closed 90 days after the last reply. New replies are no longer allowed.