OutOfMemoryError occurred in coordinating node #49699

wyukawa · 2019-11-29T01:51:50Z

Describe the feature:

Elasticsearch version (bin/elasticsearch --version):
7.4.2

Plugins installed: []

JVM version (java -version):

# /usr/share/elasticsearch/jdk/bin/java -version
openjdk version "13.0.1" 2019-10-15
OpenJDK Runtime Environment AdoptOpenJDK (build 13.0.1+9)
OpenJDK 64-Bit Server VM AdoptOpenJDK (build 13.0.1+9, mixed mode, sharing)

JVM option

/usr/share/elasticsearch/jdk/bin/java -Xms16g -Xmx16g -XX:+UseConcMarkSweepGC -XX:CMSInitiatingOccupancyFraction=75 -XX:+UseCMSInitiatingOccupancyOnly -Des.networkaddress.cache.ttl=60 -Des.networkaddress.cache.negative.ttl=10 -XX:+AlwaysPreTouch -Xss1m -Djava.awt.headless=true -Dfile.encoding=UTF-8 -Djna.nosys=true -XX:-OmitStackTraceInFastThrow -Dio.netty.noUnsafe=true -Dio.netty.noKeySetOptimization=true -Dio.netty.recycler.maxCapacityPerThread=0 -Dio.netty.allocator.numDirectArenas=0 -Dlog4j.shutdownHookEnabled=false -Dlog4j2.disable.jmx=true -Djava.io.tmpdir=/tmp/elasticsearch-14015835058529761743 -XX:+HeapDumpOnOutOfMemoryError -XX:HeapDumpPath=/var/lib/elasticsearch -XX:ErrorFile=/var/log/elasticsearch/hs_err_pid%p.log -Xlog:gc*,gc+age=trace,safepoint:file=/var/log/elasticsearch/gc.log:utctime,pid,tags:filecount=32,filesize=64m -Djava.locale.providers=COMPAT -Dio.netty.allocator.type=pooled -XX:MaxDirectMemorySize=10737418240 -Des.path.home=/usr/share/elasticsearch -Des.path.conf=/etc/elasticsearch -Des.distribution.flavor=default -Des.distribution.type=rpm -Des.bundled_jdk=true -cp /usr/share/elasticsearch/lib/* org.elasticsearch.bootstrap.Elasticsearch -p /var/run/elasticsearch/elasticsearch.pid --quiet

OS version (uname -a if on a Unix-like system):

# uname -a
Linux ... 3.10.0-1062.1.2.el7.x86_64 #1 SMP Mon Sep 30 14:19:46 UTC 2019 x86_64 x86_64 x86_64 GNU/Linux

Description of the problem including expected versus actual behavior:
OutOfMemoryError occurred in the coordinating node which is not master/data node.
We have 3 coordinating nodes.

Java heap of the coordinating node is 16GB.
After this issue, I increase java heap to 20GB.

Steps to reproduce:
I'm sorry not to reproduce...

Please include a minimal but complete recreation of the problem, including
(e.g.) index creation, mappings, settings, query etc. The easier you make for
us to reproduce it, the more likely that somebody will take the time to look at it.

Provide logs (if relevant):

java.lang.OutOfMemoryError: Java heap space
        at io.netty.util.internal.PlatformDependent.allocateUninitializedArray(PlatformDependent.java:206) ~[?:?]
        at io.netty.buffer.PoolArena$HeapArena.newByteArray(PoolArena.java:679) ~[?:?]
        at io.netty.buffer.PoolArena$HeapArena.newChunk(PoolArena.java:689) ~[?:?]
        at io.netty.buffer.PoolArena.allocateNormal(PoolArena.java:245) ~[?:?]
        at io.netty.buffer.PoolArena.allocate(PoolArena.java:227) ~[?:?]
        at io.netty.buffer.PoolArena.reallocate(PoolArena.java:400) ~[?:?]
        at io.netty.buffer.PooledByteBuf.capacity(PooledByteBuf.java:119) ~[?:?]
        at io.netty.buffer.AbstractByteBuf.ensureWritable0(AbstractByteBuf.java:303) ~[?:?]
        at io.netty.buffer.AbstractByteBuf.writeBytes(AbstractByteBuf.java:1120) ~[?:?]
        at org.elasticsearch.transport.CopyBytesSocketChannel.doReadBytes(CopyBytesSocketChannel.java:125) ~[?:?]
        at io.netty.channel.nio.AbstractNioByteChannel$NioByteUnsafe.read(AbstractNioByteChannel.java:148) ~[?:?]
        at io.netty.channel.nio.NioEventLoop.processSelectedKey(NioEventLoop.java:697) ~[?:?]
        at io.netty.channel.nio.NioEventLoop.processSelectedKeysPlain(NioEventLoop.java:597) ~[?:?]
        at io.netty.channel.nio.NioEventLoop.processSelectedKeys(NioEventLoop.java:551) ~[?:?]
        at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:511) ~[?:?]
        at io.netty.util.concurrent.SingleThreadEventExecutor$5.run(SingleThreadEventExecutor.java:918) ~[?:?]
        at io.netty.util.internal.ThreadExecutorMap$2.run(ThreadExecutorMap.java:74) ~[?:?]
        at java.lang.Thread.run(Thread.java:830) [?:?]

Eclipse Memory Analyzer result

The text was updated successfully, but these errors were encountered:

elasticmachine · 2019-11-29T19:30:57Z

Pinging @elastic/es-distributed (:Distributed/Network)

original-brownbear · 2019-11-29T19:33:44Z

@wyukawa Would you be able to provide a better heap dump/analysis that contains the actual classnames for the objects that are taking up most of the heap here?

wyukawa · 2019-12-02T05:30:05Z

Actually I really want to know the actual class name but the resut html report of Eclipse Memory Analyzer with https://gist.github.com/mrbuk/5726c469234238a26327 shows as follows

One instance of "Unresolved Name 0x7f1ea1a113c0" loaded by "jdk.internal.loader.ClassLoaders$AppClassLoader @ 0x429990548" occupies 13,640,405,400 (79.84%) bytes. The memory is accumulated in one instance of "java.lang.Object[]" loaded by "<system class loader>".

It seems that byte [] in netty has huge memory.
https://github.com/netty/netty/blob/netty-4.1.38.Final/common/src/main/java/io/netty/util/internal/PlatformDependent.java#L206

original-brownbear · 2019-12-02T11:23:36Z

@wyukawa you could use a different tool to analyze the heap dump. Maybe try visualVM? I think this issue may just be a manifestation of the things discussed in #44484 but lets make sure of that if possible.

wyukawa · 2019-12-03T04:15:45Z

Unfortunately, visualVM doesn't work well in my Mac...
But actually, network traffic between nodes increased about 6,7 times during the outage.

wyukawa · 2019-12-03T06:46:08Z

visualvm with jdk12 worked!

original-brownbear · 2019-12-03T06:53:23Z

@wyukawa interesting. Any indication where these byte[] are referenced from or were created?

wyukawa · 2019-12-03T07:33:20Z

hm, I'm not sure but the following screenshot might be helpful to you.

original-brownbear · 2019-12-03T07:50:44Z

@wyukawa ah, that looks like http request objects from the fields in it :) A fix that should way improve this situation is incoming in #44564

The way things currently work, we read up to 1M from the channel and then potentially force all of it into the `ByteBuf` passed by Netty. Since that `ByteBuf` tends to by default be `64k` in size, large reads will force the buffer to grow, completely circumventing the logic of `allocHandle`. This seems like it could break `io.netty.channel.RecvByteBufAllocator.Handle#continueReading` since that method for the fixed-size allocator does check whether the last read was equal to the attempted read size. So if we set `64k` because that's what the buffer size is, then wirte `1M` to the buffer we will stop reading on the IO loop, even though the channel may still have bytes that we can read right away. More imporatantly though, this can lead to running OOM quite easily under IO pressure as we are forcing the heap buffers passed to the read to `reallocate`. Closes elastic#49699

* Stop Allocating Buffers in CopyBytesSocketChannel (#49825) The way things currently work, we read up to 1M from the channel and then potentially force all of it into the `ByteBuf` passed by Netty. Since that `ByteBuf` tends to by default be `64k` in size, large reads will force the buffer to grow, completely circumventing the logic of `allocHandle`. This seems like it could break `io.netty.channel.RecvByteBufAllocator.Handle#continueReading` since that method for the fixed-size allocator does check whether the last read was equal to the attempted read size. So if we set `64k` because that's what the buffer size is, then wirte `1M` to the buffer we will stop reading on the IO loop, even though the channel may still have bytes that we can read right away. More imporatantly though, this can lead to running OOM quite easily under IO pressure as we are forcing the heap buffers passed to the read to `reallocate`. Closes #49699

The way things currently work, we read up to 1M from the channel and then potentially force all of it into the `ByteBuf` passed by Netty. Since that `ByteBuf` tends to by default be `64k` in size, large reads will force the buffer to grow, completely circumventing the logic of `allocHandle`. This seems like it could break `io.netty.channel.RecvByteBufAllocator.Handle#continueReading` since that method for the fixed-size allocator does check whether the last read was equal to the attempted read size. So if we set `64k` because that's what the buffer size is, then wirte `1M` to the buffer we will stop reading on the IO loop, even though the channel may still have bytes that we can read right away. More imporatantly though, this can lead to running OOM quite easily under IO pressure as we are forcing the heap buffers passed to the read to `reallocate`. Closes elastic#49699

original-brownbear added the :Distributed/Network label Nov 29, 2019

original-brownbear self-assigned this Nov 29, 2019

original-brownbear mentioned this issue Dec 3, 2019

Stop Copying Every Http Request in Message Handler #44564

Merged

original-brownbear mentioned this issue Dec 4, 2019

Stop Allocating Buffers in CopyBytesSocketChannel #49825

Merged

original-brownbear closed this in elastic/elasticsearch@7a363f4 Dec 4, 2019

original-brownbear mentioned this issue Dec 4, 2019

Stop Allocating Buffers in CopyBytesSocketChannel (#49825) #49832

Merged

elastic / elasticsearch Public

OutOfMemoryError occurred in coordinating node #49699

OutOfMemoryError occurred in coordinating node #49699

wyukawa commented Nov 29, 2019 •

edited

elasticmachine commented Nov 29, 2019

original-brownbear commented Nov 29, 2019

wyukawa commented Dec 2, 2019 •

edited

original-brownbear commented Dec 2, 2019

wyukawa commented Dec 3, 2019

wyukawa commented Dec 3, 2019

original-brownbear commented Dec 3, 2019

wyukawa commented Dec 3, 2019

original-brownbear commented Dec 3, 2019 •

edited

elastic / elasticsearch Public

OutOfMemoryError occurred in coordinating node #49699

OutOfMemoryError occurred in coordinating node #49699

Comments

wyukawa commented Nov 29, 2019 • edited

elasticmachine commented Nov 29, 2019

original-brownbear commented Nov 29, 2019

wyukawa commented Dec 2, 2019 • edited

original-brownbear commented Dec 2, 2019

wyukawa commented Dec 3, 2019

wyukawa commented Dec 3, 2019

original-brownbear commented Dec 3, 2019

wyukawa commented Dec 3, 2019

original-brownbear commented Dec 3, 2019 • edited

wyukawa commented Nov 29, 2019 •

edited

wyukawa commented Dec 2, 2019 •

edited

original-brownbear commented Dec 3, 2019 •

edited