Getting java.lang.OutOfMemoryError: Direct buffer memory

[vleushin]

Lettuce version: 5.0.2.RELEASE
Reproducible in Linux (Kubernetes), Windows (my local machine), likely everywhere

I've started testing Redis cluster in Kubernetes. So far -- not bad, all failover scenarios worked fine, but there was one big problem -- memory leaks. It was not evident for me at first (because it was direct memory leak and I was looking at heap charts), but I think I tackled two cases.

First one is topology refresh. I have single node redis cluster (redis-cluster) in docker compose for local testing.
With this options:

ClusterTopologyRefreshOptions.builder()
    .enablePeriodicRefresh(Duration.ofSeconds(2)) // anything will do, but small value will lead to exception faster
    .enableAllAdaptiveRefreshTriggers()
    .build()

And small direct memory size, e.g. -XX:MaxDirectMemorySize=100M or 200M, I can get OOM exception in 1-2 minutes. Exception looks like this:

2018-02-17 13:33:17.243 [WARN] [lettuce-eventExecutorLoop-63-8] [i.l.c.c.t.ClusterTopologyRefresh] - Cannot retrieve partition view from RedisURI [host='redis-cluster', port=7000], error: java.util.concurrent.ExecutionException: java.lang.NullPointerException
2018-02-17 13:33:17.243 [WARN] [lettuce-nioEventLoop-65-3] [i.l.c.p.CommandHandler] - null Unexpected exception during request: java.lang.NullPointerException
java.lang.NullPointerException: null
	at io.lettuce.core.protocol.CommandHandler.channelRead(CommandHandler.java:500) ~[lettuce-core-5.0.2.RELEASE.jar:?]
	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:362) [netty-transport-4.1.21.Final.jar:4.1.21.Final]
	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:348) [netty-transport-4.1.21.Final.jar:4.1.21.Final]
	at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:340) [netty-transport-4.1.21.Final.jar:4.1.21.Final]
	at io.netty.channel.ChannelInboundHandlerAdapter.channelRead(ChannelInboundHandlerAdapter.java:86) [netty-transport-4.1.21.Final.jar:4.1.21.Final]
	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:362) [netty-transport-4.1.21.Final.jar:4.1.21.Final]
	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:348) [netty-transport-4.1.21.Final.jar:4.1.21.Final]
	at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:340) [netty-transport-4.1.21.Final.jar:4.1.21.Final]
	at io.netty.channel.ChannelInboundHandlerAdapter.channelRead(ChannelInboundHandlerAdapter.java:86) [netty-transport-4.1.21.Final.jar:4.1.21.Final]
	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:362) [netty-transport-4.1.21.Final.jar:4.1.21.Final]
	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:348) [netty-transport-4.1.21.Final.jar:4.1.21.Final]
	at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:340) [netty-transport-4.1.21.Final.jar:4.1.21.Final]
	at io.netty.channel.DefaultChannelPipeline$HeadContext.channelRead(DefaultChannelPipeline.java:1414) [netty-transport-4.1.21.Final.jar:4.1.21.Final]
	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:362) [netty-transport-4.1.21.Final.jar:4.1.21.Final]
	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:348) [netty-transport-4.1.21.Final.jar:4.1.21.Final]
	at io.netty.channel.DefaultChannelPipeline.fireChannelRead(DefaultChannelPipeline.java:945) [netty-transport-4.1.21.Final.jar:4.1.21.Final]
	at io.netty.channel.nio.AbstractNioByteChannel$NioByteUnsafe.read(AbstractNioByteChannel.java:141) [netty-transport-4.1.21.Final.jar:4.1.21.Final]
	at io.netty.channel.nio.NioEventLoop.processSelectedKey(NioEventLoop.java:645) [netty-transport-4.1.21.Final.jar:4.1.21.Final]
	at io.netty.channel.nio.NioEventLoop.processSelectedKeysPlain(NioEventLoop.java:545) [netty-transport-4.1.21.Final.jar:4.1.21.Final]
	at io.netty.channel.nio.NioEventLoop.processSelectedKeys(NioEventLoop.java:499) [netty-transport-4.1.21.Final.jar:4.1.21.Final]
	at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:459) [netty-transport-4.1.21.Final.jar:4.1.21.Final]
	at io.netty.util.concurrent.SingleThreadEventExecutor$5.run(SingleThreadEventExecutor.java:886) [netty-common-4.1.21.Final.jar:4.1.21.Final]
	at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30) [netty-common-4.1.21.Final.jar:4.1.21.Final]
	at java.lang.Thread.run(Thread.java:844) [?:?]

Looks like Netty is out of direct memory.

Second case I'm less sure, I did not do extensive testing, but I think they are connected. I have 7 redis node cluster in our Kubernetes environment. We killed one master to see if it will failover. It did, topology refreshed, everything seemed OK. But in background Lettuce kept pinging/trying to connect to dead node (only seen when turned on Lettuce debug log), and direct memory quickly dried up and node died.

Any thoughts?

[vleushin]

To clarify:

• In first scenario I just launch my server node with topology refresh. Do nothing, just wait, OOM
• Second scenario. Launch server node (without topology refresh). Seems no leaks. Kill one node, Everything seems to work. Wait little bit. OOM.

[mp911de]

Can you please provide the stack trace showing the OOM. Getting a heap dump with heap buffers would be ideal. You can set -Dio.netty.noPreferDirect=true to prefer heap buffers and adjust the memory size with -Xmx=… to limit the heap size through JVM settings.

[vleushin]

I've created minimal project where it is easy to reproduce it: https://github.com/vleushin/lettuce-oom , takes less than a minute. Sort of illustrates what I have in real -- tons of microservices (GRPC), inside many of them there is Redis backend, so I end up with bunch of Redis clients.

Exception:

febr. 19, 2018 9:16:38 AM io.lettuce.core.protocol.CommandHandler exceptionCaught
WARNING: null Unexpected exception during request: java.lang.NullPointerException
java.lang.NullPointerException

febr. 19, 2018 9:16:38 AM io.lettuce.core.protocol.CommandHandler exceptionCaught
WARNING: null Unexpected exception during request: io.netty.util.internal.OutOfDirectMemoryError: failed to allocate 16777216 byte(s) of direct memory (used: 100663296, max: 104857600)
io.netty.util.internal.OutOfDirectMemoryError: failed to allocate 16777216 byte(s) of direct memory (used: 100663296, max: 104857600)
	at io.netty.util.internal.PlatformDependent.incrementMemoryCounter(PlatformDependent.java:640)
	at io.netty.util.internal.PlatformDependent.allocateDirectNoCleaner(PlatformDependent.java:594)
	at io.netty.buffer.PoolArena$DirectArena.allocateDirect(PoolArena.java:764)
	at io.netty.buffer.PoolArena$DirectArena.newChunk(PoolArena.java:740)
	at io.netty.buffer.PoolArena.allocateNormal(PoolArena.java:244)
	at io.netty.buffer.PoolArena.allocate(PoolArena.java:214)
	at io.netty.buffer.PoolArena.allocate(PoolArena.java:146)
	at io.netty.buffer.PooledByteBufAllocator.newDirectBuffer(PooledByteBufAllocator.java:324)
	at io.netty.buffer.AbstractByteBufAllocator.directBuffer(AbstractByteBufAllocator.java:185)
	at io.netty.buffer.AbstractByteBufAllocator.directBuffer(AbstractByteBufAllocator.java:176)
	at io.netty.buffer.AbstractByteBufAllocator.ioBuffer(AbstractByteBufAllocator.java:137)
	at io.netty.channel.DefaultMaxMessagesRecvByteBufAllocator$MaxMessageHandle.allocate(DefaultMaxMessagesRecvByteBufAllocator.java:114)
	at io.netty.channel.nio.AbstractNioByteChannel$NioByteUnsafe.read(AbstractNioByteChannel.java:125)
	at io.netty.channel.nio.NioEventLoop.processSelectedKey(NioEventLoop.java:645)
	at io.netty.channel.nio.NioEventLoop.processSelectedKeysOptimized(NioEventLoop.java:580)
	at io.netty.channel.nio.NioEventLoop.processSelectedKeys(NioEventLoop.java:497)
	at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:459)
	at io.netty.util.concurrent.SingleThreadEventExecutor$5.run(SingleThreadEventExecutor.java:886)
	at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30)
	at java.lang.Thread.run(Thread.java:745)

BTW, in some setups I get OutOfDirectMemoryError in some OutOfMemory.

Heapdump is here: https://github.com/vleushin/lettuce-oom/releases/download/0.1.0/heapdump-1519024984196.zip

[mp911de]

Awesome, thanks a lot. I'll take a deeper look as soon as I can.

[vleushin]

Also, sometimes I get this exception:

febr. 19, 2018 10:31:30 AM io.lettuce.core.cluster.ClusterTopologyRefreshScheduler$ClusterTopologyRefreshTask run
WARNING: Cannot refresh Redis Cluster topology
io.lettuce.core.RedisException: Cannot retrieve initial cluster partitions from initial URIs [RedisURI [host='127.0.0.1', port=7000]]
	at io.lettuce.core.cluster.RedisClusterClient.loadPartitions(RedisClusterClient.java:808)
	at io.lettuce.core.cluster.RedisClusterClient.reloadPartitions(RedisClusterClient.java:732)
	at io.lettuce.core.cluster.ClusterTopologyRefreshScheduler$ClusterTopologyRefreshTask.run(ClusterTopologyRefreshScheduler.java:197)
	at io.netty.util.concurrent.PromiseTask$RunnableAdapter.call(PromiseTask.java:38)
	at io.netty.util.concurrent.PromiseTask.run(PromiseTask.java:73)
	at io.netty.util.concurrent.DefaultEventExecutor.run(DefaultEventExecutor.java:66)
	at io.netty.util.concurrent.SingleThreadEventExecutor$5.run(SingleThreadEventExecutor.java:886)
	at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30)
	at java.lang.Thread.run(Thread.java:745)
Caused by: io.lettuce.core.RedisConnectionException: Unable to establish a connection to Redis Cluster
	at io.lettuce.core.cluster.topology.AsyncConnections.get(AsyncConnections.java:84)
	at io.lettuce.core.cluster.topology.ClusterTopologyRefresh.loadViews(ClusterTopologyRefresh.java:68)
	at io.lettuce.core.cluster.RedisClusterClient.loadPartitions(RedisClusterClient.java:787)
	... 8 more
	Suppressed: io.lettuce.core.RedisConnectionException: Unable to connect to 127.0.0.1:7000
		at io.lettuce.core.cluster.topology.ClusterTopologyRefresh.lambda$getConnections$2(ClusterTopologyRefresh.java:226)
		at java.util.concurrent.CompletableFuture.uniWhenComplete(CompletableFuture.java:760)
		at java.util.concurrent.CompletableFuture$UniWhenComplete.tryFire(CompletableFuture.java:736)
		at java.util.concurrent.CompletableFuture.postComplete(CompletableFuture.java:474)
		at java.util.concurrent.CompletableFuture.completeExceptionally(CompletableFuture.java:1977)
		at io.lettuce.core.AbstractRedisClient.lambda$initializeChannelAsync$1(AbstractRedisClient.java:275)
		at io.netty.util.concurrent.DefaultPromise.notifyListener0(DefaultPromise.java:512)
		at io.netty.util.concurrent.DefaultPromise.notifyListenersNow(DefaultPromise.java:486)
		at io.netty.util.concurrent.DefaultPromise.notifyListeners(DefaultPromise.java:425)
		at io.netty.util.concurrent.DefaultPromise.tryFailure(DefaultPromise.java:122)
		at io.netty.channel.AbstractChannel$AbstractUnsafe.safeSetFailure(AbstractChannel.java:987)
		at io.netty.channel.AbstractChannel$AbstractUnsafe.ensureOpen(AbstractChannel.java:970)
		at io.netty.channel.nio.AbstractNioChannel$AbstractNioUnsafe.connect(AbstractNioChannel.java:243)
		at io.netty.channel.DefaultChannelPipeline$HeadContext.connect(DefaultChannelPipeline.java:1346)
		at io.netty.channel.AbstractChannelHandlerContext.invokeConnect(AbstractChannelHandlerContext.java:545)
		at io.netty.channel.AbstractChannelHandlerContext.connect(AbstractChannelHandlerContext.java:530)
		at io.netty.channel.AbstractChannelHandlerContext.connect(AbstractChannelHandlerContext.java:512)
		at io.netty.channel.DefaultChannelPipeline.connect(DefaultChannelPipeline.java:1004)
		at io.netty.channel.AbstractChannel.connect(AbstractChannel.java:259)
		at io.netty.bootstrap.Bootstrap$3.run(Bootstrap.java:252)
		at io.netty.util.concurrent.AbstractEventExecutor.safeExecute$$$capture(AbstractEventExecutor.java:163)
		at io.netty.util.concurrent.AbstractEventExecutor.safeExecute(AbstractEventExecutor.java)
		at io.netty.util.concurrent.SingleThreadEventExecutor.runAllTasks(SingleThreadEventExecutor.java:404)
		at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:463)
		... 3 more
	Caused by: java.util.concurrent.CompletionException: java.nio.channels.ClosedChannelException
		at java.util.concurrent.CompletableFuture.encodeThrowable(CompletableFuture.java:292)
		at java.util.concurrent.CompletableFuture.completeThrowable(CompletableFuture.java:308)
		at java.util.concurrent.CompletableFuture.uniApply(CompletableFuture.java:593)
		at java.util.concurrent.CompletableFuture$UniApply.tryFire(CompletableFuture.java:577)
		... 24 more
	Caused by: java.nio.channels.ClosedChannelException
		at io.netty.channel.AbstractChannel$AbstractUnsafe.ensureOpen(...)(Unknown Source)

This is one I saw initially in logging and was very confused -- because there were valid and working RedisURIs, but this one consequence of OOM.

[vleushin]

@mp911de Hey! Any news? Have you managed to reproduce the problem?

[mp911de]

I'm busy with other things right now. This one gets my attention as one of the next issues.

[vleushin]

Sure, no rush. I turned off refresh for now. Seems no memory leaks, at least on couple day scale.

[mp911de]

I took a look at the heap dump and I have the slight feeling that the memory consumption is a consequence of the runtime environment.

Netty creates tons of threads/event loops – too many if you consider the memory limit of 100MB.

Your heap dump shows the event loops. Looking at your code, you create lots of RedisClusterClient instances which create lots of event loops. Please reuse ClientResources as much as possible, ideally a single instance per JVM.

This will reduce on one hand the number of lingering threads. On the other hand, every netty thread has a thread-local memory buffer pool cache:

io.netty.buffer.PoolThreadCache$SubPageMemoryRegionCache

The more threads you spin up, the more memory caches are allocated and the more memory buffers are contained within such a cache and the more memory you require.

The more threads you use, the more (direct) memory you require. I'm not fully aware since which JVM version cgroup limits (especially processor count) is respected. By default, Lettuce creates 2 * Runtime.availableProcessors() threads. You can limit the number by either setting -Dio.netty.eventLoopThreads=… or via the API: DefaultClientResources.builder().ioThreadPoolSize(4).computationThreadPoolSize(4).

[vleushin]

@mp911de Point taken. Will be using as few ClientResources as possible. For cluster this will work, but for non-cluster I will still need at least one for each DB in Redis, right?

But I still suspect there is the problem. My production nodes (-Xmx=1G) eventually get OutOfDirectMemory anyway, so I turn off periodic refresh. Should I increase memory -- to check if I still be getting OutOfDirectMemory?

Also, this: vleushin/lettuce-oom@49cabc5#r27648655 . I'm getting this error with single RedisClusterClient and single-node Redis cluster.

[mp911de]

ClientResources encapsulate thread pools, basically. You can share it amongst RedisClient and RedisClusterClient instances within a single JVM. In general, you need a single RedisClient for multiple servers/databases/connections (a singleton in your JVM is fine, too). For clusters, you need a RedisClusterClient instance per cluster each.

If you still run into issues, please use heap-buffers and please provide a heap dump. If there's a problem, we will find and fix it!

[mp911de]

I think we found the cause. The OOME looks related to a connection leak reported in #721.

[vleushin]

@mp911de Great! You can close this ticket, I will follow on #721