Closed donggyu81 closed 3 years ago
Out of interest, can you attach a debug log from the startup sequence so we can cross-check it whether there's an unusually long delay?
@mp911de sorry for late response. i've attached a log.
log of test_lettuce_connection()
18:50:37.005 [main] INFO com.naver.c2c.support.cache.NbaseArcSeedAddressProcessor - Get nbase-arc cluster nodes from seed address. nodes: 10.105.66.206:21339,10.105.66.206:21349
18:50:37.020 [main] DEBUG io.netty.util.internal.logging.InternalLoggerFactory - Using SLF4J as the default logging framework
18:50:37.044 [main] DEBUG io.lettuce.core.resource.DefaultClientResources - -Dio.netty.eventLoopThreads: 8
18:50:37.051 [main] DEBUG io.lettuce.core.resource.DefaultEventLoopGroupProvider - Creating executor io.netty.util.concurrent.DefaultEventExecutorGroup
18:50:37.070 [main] DEBUG io.netty.util.internal.InternalThreadLocalMap - -Dio.netty.threadLocalMap.stringBuilder.initialSize: 1024
18:50:37.070 [main] DEBUG io.netty.util.internal.InternalThreadLocalMap - -Dio.netty.threadLocalMap.stringBuilder.maxSize: 4096
18:50:37.074 [main] DEBUG io.netty.util.ResourceLeakDetector - -Dio.netty.leakDetection.level: simple
18:50:37.074 [main] DEBUG io.netty.util.ResourceLeakDetector - -Dio.netty.leakDetection.targetRecords: 4
18:50:37.076 [main] DEBUG io.netty.util.ResourceLeakDetectorFactory - Loaded default ResourceLeakDetector: io.netty.util.ResourceLeakDetector@3b74ac8
18:50:37.091 [main] DEBUG io.netty.util.internal.PlatformDependent - Platform: Windows
18:50:37.092 [main] DEBUG io.netty.util.internal.PlatformDependent0 - -Dio.netty.noUnsafe: false
18:50:37.093 [main] DEBUG io.netty.util.internal.PlatformDependent0 - Java version: 11
18:50:37.094 [main] DEBUG io.netty.util.internal.PlatformDependent0 - sun.misc.Unsafe.theUnsafe: available
18:50:37.095 [main] DEBUG io.netty.util.internal.PlatformDependent0 - sun.misc.Unsafe.copyMemory: available
18:50:37.096 [main] DEBUG io.netty.util.internal.PlatformDependent0 - java.nio.Buffer.address: available
18:50:37.099 [main] DEBUG io.netty.util.internal.PlatformDependent0 - direct buffer constructor: unavailable
java.lang.UnsupportedOperationException: Reflective setAccessible(true) disabled
at io.netty.util.internal.ReflectionUtil.trySetAccessible(ReflectionUtil.java:31)
at io.netty.util.internal.PlatformDependent0$4.run(PlatformDependent0.java:233)
at java.base/java.security.AccessController.doPrivileged(Native Method)
at io.netty.util.internal.PlatformDependent0.<clinit>(PlatformDependent0.java:227)
at io.netty.util.internal.PlatformDependent.isAndroid(PlatformDependent.java:289)
at io.netty.util.internal.PlatformDependent.<clinit>(PlatformDependent.java:92)
at io.netty.util.HashedWheelTimer.<init>(HashedWheelTimer.java:109)
at io.netty.util.HashedWheelTimer.<init>(HashedWheelTimer.java:218)
at io.netty.util.HashedWheelTimer.<init>(HashedWheelTimer.java:197)
at io.netty.util.HashedWheelTimer.<init>(HashedWheelTimer.java:179)
at io.netty.util.HashedWheelTimer.<init>(HashedWheelTimer.java:163)
at io.lettuce.core.resource.DefaultClientResources.<init>(DefaultClientResources.java:178)
at io.lettuce.core.resource.DefaultClientResources$Builder.build(DefaultClientResources.java:563)
at io.lettuce.core.resource.DefaultClientResources.create(DefaultClientResources.java:243)
at io.lettuce.core.AbstractRedisClient.<init>(AbstractRedisClient.java:102)
at io.lettuce.core.RedisClient.<init>(RedisClient.java:94)
at io.lettuce.core.RedisClient.create(RedisClient.java:143)
at com.naver.c2c.support.redis.RedisConnectionTest.test_lettuce_connection(RedisConnectionTest.java:45)
at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.base/java.lang.reflect.Method.invoke(Method.java:566)
at org.junit.runners.model.FrameworkMethod$1.runReflectiveCall(FrameworkMethod.java:50)
at org.junit.internal.runners.model.ReflectiveCallable.run(ReflectiveCallable.java:12)
at org.junit.runners.model.FrameworkMethod.invokeExplosively(FrameworkMethod.java:47)
at org.junit.internal.runners.statements.InvokeMethod.evaluate(InvokeMethod.java:17)
at org.junit.runners.ParentRunner.runLeaf(ParentRunner.java:325)
at org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:78)
at org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:57)
at org.junit.runners.ParentRunner$3.run(ParentRunner.java:290)
at org.junit.runners.ParentRunner$1.schedule(ParentRunner.java:71)
at org.junit.runners.ParentRunner.runChildren(ParentRunner.java:288)
at org.junit.runners.ParentRunner.access$000(ParentRunner.java:58)
at org.junit.runners.ParentRunner$2.evaluate(ParentRunner.java:268)
at org.junit.runners.ParentRunner.run(ParentRunner.java:363)
at org.junit.runner.JUnitCore.run(JUnitCore.java:137)
at com.intellij.junit4.JUnit4IdeaTestRunner.startRunnerWithArgs(JUnit4IdeaTestRunner.java:68)
at com.intellij.rt.junit.IdeaTestRunner$Repeater.startRunnerWithArgs(IdeaTestRunner.java:33)
at com.intellij.rt.junit.JUnitStarter.prepareStreamsAndStart(JUnitStarter.java:230)
at com.intellij.rt.junit.JUnitStarter.main(JUnitStarter.java:58)
18:50:37.100 [main] DEBUG io.netty.util.internal.PlatformDependent0 - java.nio.Bits.unaligned: available, true
18:50:37.102 [main] DEBUG io.netty.util.internal.PlatformDependent0 - jdk.internal.misc.Unsafe.allocateUninitializedArray(int): unavailable
java.lang.IllegalAccessException: class io.netty.util.internal.PlatformDependent0$6 cannot access class jdk.internal.misc.Unsafe (in module java.base) because module java.base does not export jdk.internal.misc to unnamed module @7fbdb894
at java.base/jdk.internal.reflect.Reflection.newIllegalAccessException(Reflection.java:361)
at java.base/java.lang.reflect.AccessibleObject.checkAccess(AccessibleObject.java:591)
at java.base/java.lang.reflect.Method.invoke(Method.java:558)
at io.netty.util.internal.PlatformDependent0$6.run(PlatformDependent0.java:347)
at java.base/java.security.AccessController.doPrivileged(Native Method)
at io.netty.util.internal.PlatformDependent0.<clinit>(PlatformDependent0.java:338)
at io.netty.util.internal.PlatformDependent.isAndroid(PlatformDependent.java:289)
at io.netty.util.internal.PlatformDependent.<clinit>(PlatformDependent.java:92)
at io.netty.util.HashedWheelTimer.<init>(HashedWheelTimer.java:109)
at io.netty.util.HashedWheelTimer.<init>(HashedWheelTimer.java:218)
at io.netty.util.HashedWheelTimer.<init>(HashedWheelTimer.java:197)
at io.netty.util.HashedWheelTimer.<init>(HashedWheelTimer.java:179)
at io.netty.util.HashedWheelTimer.<init>(HashedWheelTimer.java:163)
at io.lettuce.core.resource.DefaultClientResources.<init>(DefaultClientResources.java:178)
at io.lettuce.core.resource.DefaultClientResources$Builder.build(DefaultClientResources.java:563)
at io.lettuce.core.resource.DefaultClientResources.create(DefaultClientResources.java:243)
at io.lettuce.core.AbstractRedisClient.<init>(AbstractRedisClient.java:102)
at io.lettuce.core.RedisClient.<init>(RedisClient.java:94)
at io.lettuce.core.RedisClient.create(RedisClient.java:143)
at com.naver.c2c.support.redis.RedisConnectionTest.test_lettuce_connection(RedisConnectionTest.java:45)
at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.base/java.lang.reflect.Method.invoke(Method.java:566)
at org.junit.runners.model.FrameworkMethod$1.runReflectiveCall(FrameworkMethod.java:50)
at org.junit.internal.runners.model.ReflectiveCallable.run(ReflectiveCallable.java:12)
at org.junit.runners.model.FrameworkMethod.invokeExplosively(FrameworkMethod.java:47)
at org.junit.internal.runners.statements.InvokeMethod.evaluate(InvokeMethod.java:17)
at org.junit.runners.ParentRunner.runLeaf(ParentRunner.java:325)
at org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:78)
at org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:57)
at org.junit.runners.ParentRunner$3.run(ParentRunner.java:290)
at org.junit.runners.ParentRunner$1.schedule(ParentRunner.java:71)
at org.junit.runners.ParentRunner.runChildren(ParentRunner.java:288)
at org.junit.runners.ParentRunner.access$000(ParentRunner.java:58)
at org.junit.runners.ParentRunner$2.evaluate(ParentRunner.java:268)
at org.junit.runners.ParentRunner.run(ParentRunner.java:363)
at org.junit.runner.JUnitCore.run(JUnitCore.java:137)
at com.intellij.junit4.JUnit4IdeaTestRunner.startRunnerWithArgs(JUnit4IdeaTestRunner.java:68)
at com.intellij.rt.junit.IdeaTestRunner$Repeater.startRunnerWithArgs(IdeaTestRunner.java:33)
at com.intellij.rt.junit.JUnitStarter.prepareStreamsAndStart(JUnitStarter.java:230)
at com.intellij.rt.junit.JUnitStarter.main(JUnitStarter.java:58)
18:50:37.102 [main] DEBUG io.netty.util.internal.PlatformDependent0 - java.nio.DirectByteBuffer.<init>(long, int): unavailable
18:50:37.102 [main] DEBUG io.netty.util.internal.PlatformDependent - sun.misc.Unsafe: available
18:50:37.121 [main] DEBUG io.netty.util.internal.PlatformDependent - maxDirectMemory: 4269801472 bytes (maybe)
18:50:37.121 [main] DEBUG io.netty.util.internal.PlatformDependent - -Dio.netty.tmpdir: C:\Users\LZ\AppData\Local\Temp (java.io.tmpdir)
18:50:37.121 [main] DEBUG io.netty.util.internal.PlatformDependent - -Dio.netty.bitMode: 64 (sun.arch.data.model)
18:50:37.122 [main] DEBUG io.netty.util.internal.PlatformDependent - -Dio.netty.maxDirectMemory: -1 bytes
18:50:37.122 [main] DEBUG io.netty.util.internal.PlatformDependent - -Dio.netty.uninitializedArrayAllocationThreshold: -1
18:50:37.123 [main] DEBUG io.netty.util.internal.CleanerJava9 - java.nio.ByteBuffer.cleaner(): available
18:50:37.124 [main] DEBUG io.netty.util.internal.PlatformDependent - -Dio.netty.noPreferDirect: false
18:50:37.133 [main] DEBUG io.netty.util.internal.PlatformDependent - org.jctools-core.MpscChunkedArrayQueue: available
18:50:37.144 [main] DEBUG reactor.util.Loggers$LoggerFactory - Using Slf4j logging framework
18:50:37.241 [main] DEBUG io.lettuce.core.resource.DefaultClientResources - LatencyUtils/HdrUtils are not available, metrics are disabled
18:50:37.247 [main] DEBUG io.lettuce.core.RedisClient - Trying to get a Redis connection for: redis://10.105.66.206:21339
18:50:37.462 [main] DEBUG io.netty.buffer.PooledByteBufAllocator - -Dio.netty.allocator.numHeapArenas: 16
18:50:37.462 [main] DEBUG io.netty.buffer.PooledByteBufAllocator - -Dio.netty.allocator.numDirectArenas: 16
18:50:37.462 [main] DEBUG io.netty.buffer.PooledByteBufAllocator - -Dio.netty.allocator.pageSize: 8192
18:50:37.462 [main] DEBUG io.netty.buffer.PooledByteBufAllocator - -Dio.netty.allocator.maxOrder: 11
18:50:37.463 [main] DEBUG io.netty.buffer.PooledByteBufAllocator - -Dio.netty.allocator.chunkSize: 16777216
18:50:37.463 [main] DEBUG io.netty.buffer.PooledByteBufAllocator - -Dio.netty.allocator.tinyCacheSize: 512
18:50:37.463 [main] DEBUG io.netty.buffer.PooledByteBufAllocator - -Dio.netty.allocator.smallCacheSize: 256
18:50:37.463 [main] DEBUG io.netty.buffer.PooledByteBufAllocator - -Dio.netty.allocator.normalCacheSize: 64
18:50:37.463 [main] DEBUG io.netty.buffer.PooledByteBufAllocator - -Dio.netty.allocator.maxCachedBufferCapacity: 32768
18:50:37.463 [main] DEBUG io.netty.buffer.PooledByteBufAllocator - -Dio.netty.allocator.cacheTrimInterval: 8192
18:50:37.463 [main] DEBUG io.netty.buffer.PooledByteBufAllocator - -Dio.netty.allocator.cacheTrimIntervalMillis: 0
18:50:37.463 [main] DEBUG io.netty.buffer.PooledByteBufAllocator - -Dio.netty.allocator.useCacheForAllThreads: true
18:50:37.463 [main] DEBUG io.netty.buffer.PooledByteBufAllocator - -Dio.netty.allocator.maxCachedByteBuffersPerChunk: 1023
18:50:37.468 [main] DEBUG io.netty.buffer.ByteBufUtil - -Dio.netty.allocator.type: pooled
18:50:37.468 [main] DEBUG io.netty.buffer.ByteBufUtil - -Dio.netty.threadLocalDirectBufferSize: 0
18:50:37.468 [main] DEBUG io.netty.buffer.ByteBufUtil - -Dio.netty.maxThreadLocalCharBufferSize: 16384
18:50:37.470 [main] DEBUG io.lettuce.core.resource.KqueueProvider - Starting without optional kqueue library
18:50:37.471 [main] DEBUG io.lettuce.core.resource.EpollProvider - Starting without optional epoll library
18:50:37.472 [main] DEBUG io.lettuce.core.resource.DefaultEventLoopGroupProvider - Allocating executor io.netty.channel.nio.NioEventLoopGroup
18:50:37.472 [main] DEBUG io.lettuce.core.resource.DefaultEventLoopGroupProvider - Creating executor io.netty.channel.nio.NioEventLoopGroup
18:50:37.472 [main] DEBUG io.netty.channel.MultithreadEventLoopGroup - -Dio.netty.eventLoopThreads: 16
18:50:37.476 [main] DEBUG io.netty.channel.nio.NioEventLoop - -Dio.netty.noKeySetOptimization: false
18:50:37.476 [main] DEBUG io.netty.channel.nio.NioEventLoop - -Dio.netty.selectorAutoRebuildThreshold: 512
18:50:38.165 [main] DEBUG io.lettuce.core.resource.DefaultEventLoopGroupProvider - Adding reference to io.netty.channel.nio.NioEventLoopGroup@3174cb09, existing ref count 0
18:50:38.176 [main] DEBUG io.lettuce.core.RedisClient - Resolved SocketAddress 10.105.66.206:21339 using redis://10.105.66.206:21339
18:50:38.176 [main] DEBUG io.lettuce.core.AbstractRedisClient - Connecting to Redis at 10.105.66.206:21339
18:50:38.193 [main] DEBUG io.netty.channel.DefaultChannelId - -Dio.netty.processId: 28556 (auto-detected)
18:50:38.194 [main] DEBUG io.netty.util.NetUtil - -Djava.net.preferIPv4Stack: false
18:50:38.194 [main] DEBUG io.netty.util.NetUtil - -Djava.net.preferIPv6Addresses: false
18:50:38.788 [main] DEBUG io.netty.util.NetUtil - Loopback interface: lo (Software Loopback Interface 1, 127.0.0.1)
18:50:38.788 [main] DEBUG io.netty.util.NetUtil - Failed to get SOMAXCONN from sysctl and file \proc\sys\net\core\somaxconn. Default: 200
18:50:39.406 [main] DEBUG io.netty.channel.DefaultChannelId - -Dio.netty.machineId: 14:b3:1f:ff:fe:28:a2:5c (auto-detected)
18:50:39.456 [lettuce-nioEventLoop-4-1] DEBUG io.lettuce.core.protocol.CommandHandler - [channel=0x3c5b1bfe, [id: 0x678a9c5a] (inactive), chid=0x1] channelRegistered()
18:50:39.461 [lettuce-nioEventLoop-4-1] DEBUG io.netty.util.Recycler - -Dio.netty.recycler.maxCapacityPerThread: 4096
18:50:39.461 [lettuce-nioEventLoop-4-1] DEBUG io.netty.util.Recycler - -Dio.netty.recycler.maxSharedCapacityFactor: 2
18:50:39.461 [lettuce-nioEventLoop-4-1] DEBUG io.netty.util.Recycler - -Dio.netty.recycler.linkCapacity: 16
18:50:39.461 [lettuce-nioEventLoop-4-1] DEBUG io.netty.util.Recycler - -Dio.netty.recycler.ratio: 8
18:50:39.467 [lettuce-nioEventLoop-4-1] DEBUG io.netty.buffer.AbstractByteBuf - -Dio.netty.buffer.checkAccessible: true
18:50:39.467 [lettuce-nioEventLoop-4-1] DEBUG io.netty.buffer.AbstractByteBuf - -Dio.netty.buffer.checkBounds: true
18:50:39.467 [lettuce-nioEventLoop-4-1] DEBUG io.netty.util.ResourceLeakDetectorFactory - Loaded default ResourceLeakDetector: io.netty.util.ResourceLeakDetector@10782616
18:50:39.489 [lettuce-nioEventLoop-4-1] DEBUG io.lettuce.core.protocol.CommandHandler - [channel=0x3c5b1bfe, /10.64.80.27:65097 -> /10.105.66.206:21339, chid=0x1] write(ctx, AsyncCommand [type=HELLO, output=GenericMapOutput [output=null, error='null'], commandType=io.lettuce.core.protocol.Command], promise)
18:50:39.492 [lettuce-nioEventLoop-4-1] DEBUG io.lettuce.core.protocol.CommandEncoder - [channel=0x3c5b1bfe, /10.64.80.27:65097 -> /10.105.66.206:21339] writing command AsyncCommand [type=HELLO, output=GenericMapOutput [output=null, error='null'], commandType=io.lettuce.core.protocol.Command]
18:50:39.497 [lettuce-nioEventLoop-4-1] DEBUG io.lettuce.core.protocol.CommandHandler - [channel=0x3c5b1bfe, /10.64.80.27:65097 -> /10.105.66.206:21339, chid=0x1] Received: 30 bytes, 1 commands in the stack
18:50:39.497 [lettuce-nioEventLoop-4-1] DEBUG io.lettuce.core.protocol.CommandHandler - [channel=0x3c5b1bfe, /10.64.80.27:65097 -> /10.105.66.206:21339, chid=0x1] Stack contains: 1 commands
18:50:39.498 [lettuce-nioEventLoop-4-1] DEBUG io.lettuce.core.protocol.RedisStateMachine - Decode done, empty stack: true
18:50:39.498 [lettuce-nioEventLoop-4-1] DEBUG io.lettuce.core.protocol.CommandHandler - [channel=0x3c5b1bfe, /10.64.80.27:65097 -> /10.105.66.206:21339, chid=0x1] Completing command AsyncCommand [type=HELLO, output=GenericMapOutput [output=null, error='ERR unknown command 'HELLO''], commandType=io.lettuce.core.protocol.Command]
18:50:39.504 [lettuce-nioEventLoop-4-1] DEBUG io.lettuce.core.protocol.CommandHandler - [channel=0x3c5b1bfe, /10.64.80.27:65097 -> /10.105.66.206:21339, chid=0x1] write(ctx, AsyncCommand [type=PING, output=StatusOutput [output=null, error='null'], commandType=io.lettuce.core.protocol.Command], promise)
18:50:39.505 [lettuce-nioEventLoop-4-1] DEBUG io.lettuce.core.protocol.CommandEncoder - [channel=0x3c5b1bfe, /10.64.80.27:65097 -> /10.105.66.206:21339] writing command AsyncCommand [type=PING, output=StatusOutput [output=null, error='null'], commandType=io.lettuce.core.protocol.Command]
18:50:39.508 [lettuce-nioEventLoop-4-1] DEBUG io.lettuce.core.protocol.CommandHandler - [channel=0x3c5b1bfe, /10.64.80.27:65097 -> /10.105.66.206:21339, chid=0x1] Received: 7 bytes, 1 commands in the stack
18:50:39.508 [lettuce-nioEventLoop-4-1] DEBUG io.lettuce.core.protocol.CommandHandler - [channel=0x3c5b1bfe, /10.64.80.27:65097 -> /10.105.66.206:21339, chid=0x1] Stack contains: 1 commands
18:50:39.508 [lettuce-nioEventLoop-4-1] DEBUG io.lettuce.core.protocol.RedisStateMachine - Decode done, empty stack: true
18:50:39.508 [lettuce-nioEventLoop-4-1] DEBUG io.lettuce.core.protocol.CommandHandler - [channel=0x3c5b1bfe, /10.64.80.27:65097 -> /10.105.66.206:21339, chid=0x1] Completing command AsyncCommand [type=PING, output=StatusOutput [output=PONG, error='null'], commandType=io.lettuce.core.protocol.Command]
18:50:39.508 [lettuce-nioEventLoop-4-1] DEBUG io.lettuce.core.protocol.CommandHandler - [channel=0x3c5b1bfe, /10.64.80.27:65097 -> /10.105.66.206:21339, chid=0x1] channelActive()
18:50:39.509 [lettuce-nioEventLoop-4-1] DEBUG io.lettuce.core.protocol.DefaultEndpoint - [channel=0x3c5b1bfe, /10.64.80.27:65097 -> /10.105.66.206:21339, epid=0x1] activateEndpointAndExecuteBufferedCommands 0 command(s) buffered
18:50:39.509 [lettuce-nioEventLoop-4-1] DEBUG io.lettuce.core.protocol.DefaultEndpoint - [channel=0x3c5b1bfe, /10.64.80.27:65097 -> /10.105.66.206:21339, epid=0x1] activating endpoint
18:50:39.509 [lettuce-nioEventLoop-4-1] DEBUG io.lettuce.core.protocol.DefaultEndpoint - [channel=0x3c5b1bfe, /10.64.80.27:65097 -> /10.105.66.206:21339, epid=0x1] flushCommands()
18:50:39.509 [lettuce-nioEventLoop-4-1] DEBUG io.lettuce.core.protocol.DefaultEndpoint - [channel=0x3c5b1bfe, /10.64.80.27:65097 -> /10.105.66.206:21339, epid=0x1] flushCommands() Flushing 0 commands
18:50:39.510 [lettuce-nioEventLoop-4-1] DEBUG io.lettuce.core.protocol.ConnectionWatchdog - [channel=0x3c5b1bfe, /10.64.80.27:65097 -> /10.105.66.206:21339, last known addr=/10.105.66.206:21339] channelActive()
18:50:39.510 [lettuce-nioEventLoop-4-1] DEBUG io.lettuce.core.protocol.CommandHandler - [channel=0x3c5b1bfe, /10.64.80.27:65097 -> /10.105.66.206:21339, chid=0x1] channelActive() done
18:50:39.510 [lettuce-nioEventLoop-4-1] DEBUG io.lettuce.core.AbstractRedisClient - Connecting to Redis at 10.105.66.206:21339: Success
18:50:39.513 [main] DEBUG io.lettuce.core.RedisChannelHandler - close()
18:50:39.514 [main] DEBUG io.lettuce.core.RedisChannelHandler - closeAsync()
18:50:39.514 [main] DEBUG io.lettuce.core.protocol.DefaultEndpoint - [channel=0x3c5b1bfe, /10.64.80.27:65097 -> /10.105.66.206:21339, epid=0x1] closeAsync()
18:50:39.516 [lettuce-nioEventLoop-4-1] DEBUG io.lettuce.core.protocol.CommandHandler - [channel=0x3c5b1bfe, /10.64.80.27:65097 -> /10.105.66.206:21339, chid=0x1] channelInactive()
18:50:39.516 [main] DEBUG io.lettuce.core.resource.DefaultEventLoopGroupProvider - Creating executor io.netty.util.concurrent.DefaultEventExecutorGroup
18:50:39.516 [lettuce-nioEventLoop-4-1] DEBUG io.lettuce.core.protocol.DefaultEndpoint - [channel=0x3c5b1bfe, /10.64.80.27:65097 -> /10.105.66.206:21339, epid=0x1] deactivating endpoint handler
18:50:39.516 [main] DEBUG io.lettuce.core.resource.DefaultClientResources - LatencyUtils/HdrUtils are not available, metrics are disabled
18:50:39.516 [main] DEBUG io.lettuce.core.RedisClient - Trying to get a Redis connection for: redis://10.105.66.206:21349
18:50:39.517 [lettuce-nioEventLoop-4-1] DEBUG io.lettuce.core.protocol.CommandHandler - [channel=0x3c5b1bfe, /10.64.80.27:65097 -> /10.105.66.206:21339, chid=0x1] channelInactive() done
18:50:39.517 [main] DEBUG io.lettuce.core.resource.DefaultEventLoopGroupProvider - Allocating executor io.netty.channel.nio.NioEventLoopGroup
18:50:39.517 [main] DEBUG io.lettuce.core.resource.DefaultEventLoopGroupProvider - Creating executor io.netty.channel.nio.NioEventLoopGroup
18:50:39.517 [lettuce-nioEventLoop-4-1] DEBUG io.lettuce.core.protocol.ConnectionWatchdog - [channel=0x3c5b1bfe, /10.64.80.27:65097 -> /10.105.66.206:21339, last known addr=/10.105.66.206:21339] channelInactive()
18:50:39.517 [lettuce-nioEventLoop-4-1] DEBUG io.lettuce.core.protocol.ConnectionWatchdog - [channel=0x3c5b1bfe, /10.64.80.27:65097 -> /10.105.66.206:21339, last known addr=/10.105.66.206:21339] Reconnect scheduling disabled
18:50:39.517 [lettuce-nioEventLoop-4-1] DEBUG io.lettuce.core.protocol.CommandHandler - [channel=0x3c5b1bfe, /10.64.80.27:65097 -> /10.105.66.206:21339, chid=0x1] channelUnregistered()
18:50:39.523 [main] DEBUG io.lettuce.core.resource.DefaultEventLoopGroupProvider - Adding reference to io.netty.channel.nio.NioEventLoopGroup@11ee02f8, existing ref count 0
18:50:39.523 [main] DEBUG io.lettuce.core.RedisClient - Resolved SocketAddress 10.105.66.206:21349 using redis://10.105.66.206:21349
18:50:39.523 [main] DEBUG io.lettuce.core.AbstractRedisClient - Connecting to Redis at 10.105.66.206:21349
18:50:39.526 [lettuce-nioEventLoop-7-1] DEBUG io.lettuce.core.protocol.CommandHandler - [channel=0x31365372, [id: 0x24770f0e] (inactive), chid=0x2] channelRegistered()
18:50:39.536 [lettuce-nioEventLoop-7-1] DEBUG io.lettuce.core.protocol.CommandHandler - [channel=0x31365372, /10.64.80.27:65114 -> /10.105.66.206:21349, chid=0x2] write(ctx, AsyncCommand [type=HELLO, output=GenericMapOutput [output=null, error='null'], commandType=io.lettuce.core.protocol.Command], promise)
18:50:39.536 [lettuce-nioEventLoop-7-1] DEBUG io.lettuce.core.protocol.CommandEncoder - [channel=0x31365372, /10.64.80.27:65114 -> /10.105.66.206:21349] writing command AsyncCommand [type=HELLO, output=GenericMapOutput [output=null, error='null'], commandType=io.lettuce.core.protocol.Command]
18:50:39.539 [lettuce-nioEventLoop-7-1] DEBUG io.lettuce.core.protocol.CommandHandler - [channel=0x31365372, /10.64.80.27:65114 -> /10.105.66.206:21349, chid=0x2] Received: 30 bytes, 1 commands in the stack
18:50:39.539 [lettuce-nioEventLoop-7-1] DEBUG io.lettuce.core.protocol.CommandHandler - [channel=0x31365372, /10.64.80.27:65114 -> /10.105.66.206:21349, chid=0x2] Stack contains: 1 commands
18:50:39.539 [lettuce-nioEventLoop-7-1] DEBUG io.lettuce.core.protocol.RedisStateMachine - Decode done, empty stack: true
18:50:39.539 [lettuce-nioEventLoop-7-1] DEBUG io.lettuce.core.protocol.CommandHandler - [channel=0x31365372, /10.64.80.27:65114 -> /10.105.66.206:21349, chid=0x2] Completing command AsyncCommand [type=HELLO, output=GenericMapOutput [output=null, error='ERR unknown command 'HELLO''], commandType=io.lettuce.core.protocol.Command]
18:50:39.539 [lettuce-nioEventLoop-7-1] DEBUG io.lettuce.core.protocol.CommandHandler - [channel=0x31365372, /10.64.80.27:65114 -> /10.105.66.206:21349, chid=0x2] write(ctx, AsyncCommand [type=PING, output=StatusOutput [output=null, error='null'], commandType=io.lettuce.core.protocol.Command], promise)
18:50:39.539 [lettuce-nioEventLoop-7-1] DEBUG io.lettuce.core.protocol.CommandEncoder - [channel=0x31365372, /10.64.80.27:65114 -> /10.105.66.206:21349] writing command AsyncCommand [type=PING, output=StatusOutput [output=null, error='null'], commandType=io.lettuce.core.protocol.Command]
18:50:39.541 [lettuce-nioEventLoop-7-1] DEBUG io.lettuce.core.protocol.CommandHandler - [channel=0x31365372, /10.64.80.27:65114 -> /10.105.66.206:21349, chid=0x2] Received: 7 bytes, 1 commands in the stack
18:50:39.541 [lettuce-nioEventLoop-7-1] DEBUG io.lettuce.core.protocol.CommandHandler - [channel=0x31365372, /10.64.80.27:65114 -> /10.105.66.206:21349, chid=0x2] Stack contains: 1 commands
18:50:39.541 [lettuce-nioEventLoop-7-1] DEBUG io.lettuce.core.protocol.RedisStateMachine - Decode done, empty stack: true
18:50:39.541 [lettuce-nioEventLoop-7-1] DEBUG io.lettuce.core.protocol.CommandHandler - [channel=0x31365372, /10.64.80.27:65114 -> /10.105.66.206:21349, chid=0x2] Completing command AsyncCommand [type=PING, output=StatusOutput [output=PONG, error='null'], commandType=io.lettuce.core.protocol.Command]
18:50:39.541 [lettuce-nioEventLoop-7-1] DEBUG io.lettuce.core.protocol.CommandHandler - [channel=0x31365372, /10.64.80.27:65114 -> /10.105.66.206:21349, chid=0x2] channelActive()
18:50:39.541 [lettuce-nioEventLoop-7-1] DEBUG io.lettuce.core.protocol.DefaultEndpoint - [channel=0x31365372, /10.64.80.27:65114 -> /10.105.66.206:21349, epid=0x2] activateEndpointAndExecuteBufferedCommands 0 command(s) buffered
18:50:39.542 [lettuce-nioEventLoop-7-1] DEBUG io.lettuce.core.protocol.DefaultEndpoint - [channel=0x31365372, /10.64.80.27:65114 -> /10.105.66.206:21349, epid=0x2] activating endpoint
18:50:39.542 [lettuce-nioEventLoop-7-1] DEBUG io.lettuce.core.protocol.DefaultEndpoint - [channel=0x31365372, /10.64.80.27:65114 -> /10.105.66.206:21349, epid=0x2] flushCommands()
18:50:39.542 [lettuce-nioEventLoop-7-1] DEBUG io.lettuce.core.protocol.DefaultEndpoint - [channel=0x31365372, /10.64.80.27:65114 -> /10.105.66.206:21349, epid=0x2] flushCommands() Flushing 0 commands
18:50:39.542 [lettuce-nioEventLoop-7-1] DEBUG io.lettuce.core.protocol.ConnectionWatchdog - [channel=0x31365372, /10.64.80.27:65114 -> /10.105.66.206:21349, last known addr=/10.105.66.206:21349] channelActive()
18:50:39.542 [lettuce-nioEventLoop-7-1] DEBUG io.lettuce.core.protocol.CommandHandler - [channel=0x31365372, /10.64.80.27:65114 -> /10.105.66.206:21349, chid=0x2] channelActive() done
18:50:39.542 [lettuce-nioEventLoop-7-1] DEBUG io.lettuce.core.AbstractRedisClient - Connecting to Redis at 10.105.66.206:21349: Success
18:50:39.542 [main] DEBUG io.lettuce.core.RedisChannelHandler - close()
18:50:39.542 [main] DEBUG io.lettuce.core.RedisChannelHandler - closeAsync()
18:50:39.542 [main] DEBUG io.lettuce.core.protocol.DefaultEndpoint - [channel=0x31365372, /10.64.80.27:65114 -> /10.105.66.206:21349, epid=0x2] closeAsync()
18:50:39.543 [lettuce-nioEventLoop-7-1] DEBUG io.lettuce.core.protocol.CommandHandler - [channel=0x31365372, /10.64.80.27:65114 -> /10.105.66.206:21349, chid=0x2] channelInactive()
18:50:39.543 [lettuce-nioEventLoop-7-1] DEBUG io.lettuce.core.protocol.DefaultEndpoint - [channel=0x31365372, /10.64.80.27:65114 -> /10.105.66.206:21349, epid=0x2] deactivating endpoint handler
18:50:39.543 [lettuce-nioEventLoop-7-1] DEBUG io.lettuce.core.protocol.CommandHandler - [channel=0x31365372, /10.64.80.27:65114 -> /10.105.66.206:21349, chid=0x2] channelInactive() done
18:50:39.543 [lettuce-nioEventLoop-7-1] DEBUG io.lettuce.core.protocol.ConnectionWatchdog - [channel=0x31365372, /10.64.80.27:65114 -> /10.105.66.206:21349, last known addr=/10.105.66.206:21349] channelInactive()
18:50:39.543 [lettuce-nioEventLoop-7-1] DEBUG io.lettuce.core.protocol.ConnectionWatchdog - [channel=0x31365372, /10.64.80.27:65114 -> /10.105.66.206:21349, last known addr=/10.105.66.206:21349] Reconnect scheduling disabled
18:50:39.543 [lettuce-nioEventLoop-7-1] DEBUG io.lettuce.core.protocol.CommandHandler - [channel=0x31365372, /10.64.80.27:65114 -> /10.105.66.206:21349, chid=0x2] channelUnregistered()
18:50:39.546 [main] INFO com.naver.c2c.support.redis.RedisConnectionTest - Connection Time : 2543 ms
log of test_jedis_connection
18:50:39.552 [main] INFO com.naver.c2c.support.cache.NbaseArcSeedAddressProcessor - Get nbase-arc cluster nodes from seed address. nodes: 10.105.66.206:21339,10.105.66.206:21349
18:50:39.582 [main] INFO com.naver.c2c.support.redis.RedisConnectionTest - Connection Time : 35 ms
Lettuce uses a threaded infrastructure and booting netty including EventLoopGroups takes a bit of time. There's nothing we could do directly about it. You could try to pre-initialize Netty resources such as obtaining and releasing a buffer from ByteBufAllocator.DEFAULT
and
NioEventLoopGroup allocate = clientResources.eventLoopGroupProvider().allocate(NioEventLoopGroup.class);
allocate.submit(() -> {}); // warm the ThreadPool
clientResources.eventLoopGroupProvider().release(allocate, 0, 0, TimeUnit.NANOSECONDS);
clientResources.eventExecutorGroup().submit(() -> {
});
clientResources.eventBus().publish(new Event() {
});
Let me add also a Cluster-specific note: Lettuce obtains the Cluster topology before establishing the actual Cluster connection. Topology uses a discovery mechanism by connecting the seed nodes and discovered nodes.
You can reduce the duration for the topology retrieval by:
RedisClusterClient.create(clientResources, redisURIs)
where redisURIs
contains one or two nodes).ClusterClientOptions.builder().topologyRefreshOptions(ClusterTopologyRefreshOptions.builder().dynamicRefreshSources(false).build());
)Please let us know whether this helps.
Hello, I've implemented service using redis cluster with lettuce library. But I have difficult on lazy in first redis connection. When I tested with jedis, it has 30ms to get first connection, but tested with lettuce, it has 2600 ~ 3000 ms. How can I set lettuce configuration to reduce time to get first connection?
Stack: spring-data-redis: 2.2.7.RELEASE lettuce-core: 6.0.0.RELEASE Clustered Redis version: 5.0.5 ( Redis has clustered with 2 servers )
Configuration
Test code
Please let me know if you need any other info. Any advise will be very helpful. thank you.