Hazelcast: Member OOME hprof after client repeatedly re-connects / splits joins.

[Danny-Hazelcast]

In this job we create 1 membrer and 12 clients, clients re repeatedly split from the member
disconnection and reconnection repeatedly

https://hazelcast-l337.ci.cloudbees.com/view/split/job/split-member-client/35/console

during the run, the Member OOME

fail HzMember1HZ split_member-client_putMapHD hzcmd.map.Put threadId=1 java.lang.Exception: java.lang.OutOfMemoryError: GC overhead limit exceeded

/disk1/jenkins/workspace/split-member-client/3.10-SNAPSHOT/2018_03_29-11_26_05/member-client

http://54.82.84.143/~jenkins/workspace/split-member-client/3.10-SNAPSHOT/2018_03_29-11_26_05/member-client

output/HZ/HzMember1HZ/exception.txt
output/HZ/HzMember1HZ/HzMember1HZ.hprof
output/HZ/HzMember1HZ/HzMember1HZ.oome

Member GC show leak pattern
http://54.82.84.143/~jenkins/workspace/split-member-client/3.10-SNAPSHOT/2018_03_29-11_26_05/member-client/gc.html

this job is not normally failing, so it looks like a regression.

[tkountis]

Thread causing the leak.

"hz._hzInstance_1_HZ.IO.thread-in-0" prio=5 tid=39 RUNNABLE
    at java.lang.OutOfMemoryError.<init>(OutOfMemoryError.java:48)
    at java.nio.HeapByteBuffer.<init>(HeapByteBuffer.java:57)
       Local Variable: java.nio.HeapByteBuffer#54
    at java.nio.ByteBuffer.allocate(ByteBuffer.java:331)
    at com.hazelcast.nio.IOUtil.newByteBuffer(IOUtil.java:81)
    at com.hazelcast.nio.tcp.MemberChannelInitializer.newInputBuffer(MemberChannelInitializer.java:169)
    at com.hazelcast.nio.tcp.MemberChannelInitializer.initInboundClientProtocol(MemberChannelInitializer.java:143)
       Local Variable: com.hazelcast.nio.tcp.TcpIpConnection#12
    at com.hazelcast.nio.tcp.MemberChannelInitializer.initInbound(MemberChannelInitializer.java:84)
       Local Variable: java.lang.String#171
       Local Variable: com.hazelcast.internal.networking.nio.NioChannel#12
       Local Variable: com.hazelcast.nio.tcp.MemberChannelInitializer#1
    at com.hazelcast.internal.networking.nio.NioInboundPipeline.init(NioInboundPipeline.java:145)
    at com.hazelcast.internal.networking.nio.NioInboundPipeline.process(NioInboundPipeline.java:125)
    at com.hazelcast.internal.networking.nio.NioThread.handleSelectionKey(NioThread.java:383)
       Local Variable: com.hazelcast.internal.networking.nio.NioInboundPipeline#12
    at com.hazelcast.internal.networking.nio.NioThread.handleSelectionKeys(NioThread.java:368)
       Local Variable: com.hazelcast.internal.networking.nio.SelectorOptimizer$IteratorImpl#2
    at com.hazelcast.internal.networking.nio.NioThread.selectLoop(NioThread.java:275)
    at com.hazelcast.internal.networking.nio.NioThread.run(NioThread.java:230)

[Danny-Hazelcast]

i think is a regression it was not failing before,
GC charts from an old 3.9 run http://54.82.84.143/~jenkins/workspace/split-member-client/3.9/2017_10_23-11_26_03/gc.html

[tkountis]

the heap in this run is mostly occupied by invocations
I am not sure its a leak, we need to test this with bigger heaps and longer time, stress it more in other words.
more invocations, could just mean that they take longer to finish so they stay longer in the registry

[Danny-Hazelcast]

the history of 3.10-SANPSHOT runs are http://54.82.84.143/~jenkins/workspace/split-member-client/3.10-SNAPSHOT/

from 19-Oct-2017 Member GC is stable.
http://54.82.84.143/~jenkins/workspace/split-member-client/3.10-SNAPSHOT/2017_10_19-11_26_03/gc.html

from 29-Mar-2018 member GC show leak pattern and OOME's
http://54.82.84.143/~jenkins/workspace/split-member-client/3.10-SNAPSHOT/2018_03_29-11_26_05/member-client/gc.html

[Danny-Hazelcast]

this run https://hazelcast-l337.ci.cloudbees.com/view/split/job/split-member-client/37/console
Member has 1G heap

[taburet]

Have analyzed the logs, the operation registry size (operations.pending.invocations.count) is much higher in the latest builds, before the first failed build it was around 35 at maximum, in the latest builds it's about 150 at the OOME moment, either we are not removing the invocations from the registry at some conditions or we are able to produce/enqueue higher number of invocations now and unable to process them in time.

I suspect that is for the first reason since the operation execution queue size (executor.q.operations.size) is not growing. It feels like this commit plays some role, but I'm not 100% sure yet. Will dig more...

[Danny-Hazelcast]

this run https://hazelcast-l337.ci.cloudbees.com/view/split/job/split-member-client/37/console
Member has 1G heap

GC member show ever increasing heap usage, looking like leak, and not classic saw as seen in client side
http://54.82.84.143/~jenkins/workspace/split-member-client/3.10-SNAPSHOT/2018_04_03-12_36_11/member-client/gc.html

I also took a member hprof near the end of the run
http://54.82.84.143/~jenkins/workspace/split-member-client/3.10-SNAPSHOT/2018_04_03-12_36_11/member-client/output/HZ/HzMember1HZ/

[Danny-Hazelcast]

run 300M Member heap GC show leak pattern, but not enough time for OOME

http://54.82.84.143/~jenkins/workspace/split-member-client/3.10-SNAPSHOT/2018_04_03-14_27_05/member-client/output/HZ/HzMember1HZ/verbosegc.log.png

[taburet]

I found the reason why the invocation registry size is growing, when a client connects to the cluster it invokes CreateProxiesMessageTask, this task in turn sends PostJoinProxyOperation to every cluster member, the operation is marked as returnsResponse = false and there are no Operation.sendResponse calls for it, so the operation never ends.

The issue was not affecting the members before the introduction of CreateProxiesMessageTask because the operation was only executed as a part of OnJoinOp, which just executes the post join operations sequentially by directly calling the run method on them.

I will create a PR in a few minutes.

[Danny-Hazelcast]

@taburet ok thanks i will rerun today