Environment creation is taking too much time

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()
                couchbaseConfig.getLong(CONNECT_TIMEOUT, CONNECT_TIMEOUT_DEFAULT_VALUE)))
            .kvTimeout(Duration.ofMillis(couchbaseConfig.getLong(KV_TIMEOUT, KV_TIMEOUT_DEFAULT_VALUE))))

    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.

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.

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

thanks for in detail information.

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:       XVVVK6G61F.local
::1             XVVVK6G61F.local

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

> echo $HOST

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

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

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

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.

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.