Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

NonBlockingSocketWriter memory leak when client disconnects #12353

Closed
LoneGumMan opened this issue Feb 15, 2018 · 16 comments
Closed

NonBlockingSocketWriter memory leak when client disconnects #12353

LoneGumMan opened this issue Feb 15, 2018 · 16 comments

Comments

@LoneGumMan
Copy link

@LoneGumMan LoneGumMan commented Feb 15, 2018

The Hazelcast server instance holds on to a write buffer when a client disconnects abruptly while there is pending data to be sent (client doing a map.forEach on a large size map)

version : 3.8.9 (both server and client)
cluster size : 1 node (reproducible with more)
number of client : 1
Java version : Oracle 1.8.0_131 (with sufficiently large -Xmx to hold the map)

To reproduce.

  1. Host a large Map on a single node cluster (several hundred MB, so it'll take some time for operation to finish). Map configured with in-memory-format = BINARY, everything else default.
  2. attach jvisualvm or similar monitoring too to cluster node, this will help visualize the point in time when to kill the client. Also observe the baseline memory usage after the server node stablises with data (invoking GC couple times manually).
  3. Start a client; invoke map.forEach with some non-trivial operation (again, just to introduce delays)
  4. see jvisualvm for a memory spike, kill (kill -9, or stop debug in debugger) the client while the node's memory usage is raising
  5. Server should log something like this
2018-02-15 10:13:12,431 WARN c.h.n.t.TcpIpConnection [10.96.9.12]:4520 [sds2-regression] [3.8.9] Connection[id=17, /10.96.9.12:4520->my-server.my-network.com/10.20.160.32:49375, endpoint=[10.20.160.32]:49375, alive=false,type=JAVA_CLIENT] closed. Reason: Exception in NonBlockingSocketReader [hz.my-server-node.IO.thread-in-0]
java.io.IOException: Connection reset by peer
        at sun.nio.ch.FileDispatcherImpl.read0(Native Method) ~[?:1.8.0_131]
        at sun.nio.ch.SocketDispatcher.read(SocketDispatcher.java:39) ~[?:1.8.0_131]
        at sun.nio.ch.IOUtil.readIntoNativeBuffer(IOUtil.java:223) ~[?:1.8.0_131]
        at sun.nio.ch.IOUtil.read(IOUtil.java:197) ~[?:1.8.0_131]
        at sun.nio.ch.SocketChannelImpl.read(SocketChannelImpl.java:380) ~[?:1.8.0_131]
        at com.hazelcast.nio.tcp.DefaultSocketChannelWrapper.read(DefaultSocketChannelWrapper.java:61) ~[hazelcast-3.8.9.jar:3.8.9]
        at com.hazelcast.internal.networking.nonblocking.NonBlockingSocketReader.handle(NonBlockingSocketReader.java:150) ~[hazelcast-3.8.9.jar:3.8.9]
        at com.hazelcast.internal.networking.nonblocking.NonBlockingIOThread.handleSelectionKey(NonBlockingIOThread.java:349) [hazelcast-3.8.9.jar:3.8.9]
        at com.hazelcast.internal.networking.nonblocking.NonBlockingIOThread.handleSelectionKeys(NonBlockingIOThread.java:334) [hazelcast-3.8.9.jar:3.8.9]
        at com.hazelcast.internal.networking.nonblocking.NonBlockingIOThread.selectLoop(NonBlockingIOThread.java:252) [hazelcast-3.8.9.jar:3.8.9]
        at com.hazelcast.internal.networking.nonblocking.NonBlockingIOThread.run(NonBlockingIOThread.java:205) [hazelcast-3.8.9.jar:3.8.9]
  1. Note that the baseline memory usage of the node is now higher even after repeated GC
  2. Take a memory dump of the server node. For my case, the NonBlockingSocketWriter holds on to a ClientMessage with a large buffer inside.
    hz-memory-leak
  3. Repeating step 3 and 4 to connect and disconnect while in the middle of an operation can create more and more of these bufferred messages, eventually lead to OOME.
@vbekiaris vbekiaris modified the milestone: 3.9.3 Feb 15, 2018
@pveentjer pveentjer self-assigned this Feb 15, 2018
@pveentjer
Copy link
Member

@pveentjer pveentjer commented Feb 15, 2018

It is the TcpIpConnection holding on to the NonBlockingSocketWriter. So only when the TcpIpConnection gets gc'd, the NonBlockingSocketWriter gets gc'ed and eventually the ClientMessage/ByteBuffer.

The key question is: is this a temporary retention or permanent retention.

Based on the the memory dump I can see that the retention is caused by the invocation registry. The invocation is registered there, and through the invocation, the ClientMessageTask is retained and this stores the connection.

Eventually the invocation will complete (one way or another) and therefor the invocation will be removed from the invocation registry and therefor the retention link is removed. So there should not be a permanent memory leak.

So the question is this is a bug or if the system is behaving like designed.

So can you keep your application running and determine if eventually the memory is released?

@LoneGumMan
Copy link
Author

@LoneGumMan LoneGumMan commented Feb 15, 2018

Unfortunately, the heap dump I have contains proprietary information which I am not at liberty to make available publicly.

The retention appears to be permanent. I left the program which hosts the node to run overnight, and the program itself has a scheduled job invoking System.gc() every two minutes. Overnight, the low point of heap (no other client joined/left this single node cluster) remained the same, higher than the original steady state in step 1 / step 2.

@pveentjer
Copy link
Member

@pveentjer pveentjer commented Feb 15, 2018

Ok.. I'll set it up today and see why this client invocation isn't completing. Perhaps additional check is needed in the invocation registry to drop any invocation from a dead client.

Thanks for your very informative ticket btw!

@LoneGumMan
Copy link
Author

@LoneGumMan LoneGumMan commented Feb 23, 2018

Are you able to reproduce the problem? or was it something wrong at my end, configuration wise, which causes this?

@PJ789
Copy link

@PJ789 PJ789 commented Jul 31, 2018

We seem to have run into the same problem described here in Hazelcast 3.10.1.

We see out of memory exceptions on members when clients are forcibly disconnected from the cluster (in our case we suspect as a result of client machines being powered off without a controlled shutdown). We have several hundred clients connected to a cluster with several members.

When our heap dumps are analysed we see the ClientMessage/bytebuffer structures are holding huge amounts of memory (much more than all the ordinary data held in the application maps).

@pveentjer Please could you update us, has there been any progress toward resolving this issue? Do you have any idea when/if it will be fixed?

In the meantime, is there anything we should do to limit, or workaround, the impact of this problem?

many thanks,
PJ

@PJ789
Copy link

@PJ789 PJ789 commented Aug 1, 2018

To add a little more information taken from a JHAT analysis of a heapdump from a live member that crashed due to an OOME;-

Instance Counts for All Classes (excluding platform)
950135 instances of class com.hazelcast.client.impl.protocol.ClientMessage
950010 instances of class com.hazelcast.client.impl.protocol.util.SafeBuffer
524288 instances of class org.apache.logging.log4j.core.async.AsyncLoggerConfigDisruptor$Log4jEventWrapper
524288 instances of class org.apache.logging.log4j.core.async.RingBufferLogEvent
524288 instances of class org.apache.logging.log4j.core.time.MutableInstant
487677 instances of class org.apache.logging.log4j.util.SortedArrayStringMap
57608 instances of class com.hazelcast.spi.impl.eventservice.impl.LocalEventDispatcher
11466 instances of class com.hazelcast.internal.serialization.impl.HeapData
10205 instances of class com.fasterxml.jackson.databind.introspect.AnnotationMap
10146 instances of class org.apache.catalina.loader.ResourceEntry
6948 instances of class com.hazelcast.spi.DistributedObjectNamespace
5598 instances of class com.hazelcast.util.StateMachine
5518 instances of class com.fasterxml.jackson.databind.introspect.AnnotatedMethod
4836 instances of class com.hazelcast.util.ConcurrentReferenceHashMap$HashEntry
4722 instances of class com.fasterxml.jackson.databind.introspect.MemberKey
4652 instances of class com.hazelcast.map.impl.record.CachedDataRecordWithStats
2890 instances of class com.hazelcast.util.ConcurrentReferenceHashMap$Segment
2890 instances of class [Lcom.hazelcast.util.ConcurrentReferenceHashMap$HashEntry;
2863 instances of class org.springframework.core.annotation.AnnotationUtils$DefaultValueHolder
2830 instances of class [Lcom.hazelcast.util.ConcurrentReferenceHashMap$Segment;
2801 instances of class com.hazelcast.util.scheduler.SecondsBasedEntryTaskScheduler
2799 instances of class com.hazelcast.concurrent.lock.LockEvictionProcessor

We have attempted to decode the bytes associated with each ClientMessage. The messages appear to be async pub/sub messages. We suspect that when clients are forcibly abruptly disconnected, Hazelcast isn't clearing out a backlog of messages when the connection is dropped.

@mdogan
Copy link
Contributor

@mdogan mdogan commented Aug 1, 2018

Looks like the same or similar issue: #13388

@aras03k
Copy link

@aras03k aras03k commented Aug 4, 2018

Also seeing the same issue (v3.10.1) as the poster even with scheduled gc() every few minutes. The instance count with byte arrays keeps on rising. We were able to reproduce it in our lab by spinning up lots of clients that registers entrylisteners on a “busy” map and randomly calls lifecycleservice.terminate().

Edit: moving to 64 bit JVM with G1GC aggressive GC and string deduplication turned on improves the memory footprint, but theres no question Hazelcast retains client messages even after the client disconnects. This is observed over days of comparing heap dumps while running aforementioned torture test.

@jerrinot
Copy link
Contributor

@jerrinot jerrinot commented Sep 10, 2018

@aras03k: can you try it with 3.11-BETA-1? There has a been a related fixed merged thanks!

@LoneGumMan
Copy link
Author

@LoneGumMan LoneGumMan commented Sep 11, 2018

Yup. I see the update on #13388, and I have been waiting for 3.10.5 with bated breath.

@mmedenjak
Copy link
Contributor

@mmedenjak mmedenjak commented Sep 18, 2018

@LoneGumMan @aras03k can you please try with hazelcast 3.10.5 or 3.11-BETA-1?

@mmedenjak
Copy link
Contributor

@mmedenjak mmedenjak commented Sep 24, 2018

@LoneGumMan @aras03k any update on the issue?

@mmedenjak mmedenjak added the To Triage label Sep 25, 2018
@dbrimley
Copy link
Member

@dbrimley dbrimley commented Oct 3, 2018

@LoneGumMan Would appreciate it if you could let us know if 3.10.5 or 3.11-BETA-1 resolved this issue for you. We're keen to close this issue if that's the case.

@LoneGumMan
Copy link
Author

@LoneGumMan LoneGumMan commented Oct 4, 2018

Hi guys, my sincere apologies. Our system was in a major release the past couple weeks.

I am happy to confirm that 3.10.5 release has indeed fixed the memory retention problem caused by abruptly disconnected clients, and memory usage drops back down to base line level after some period (is there a timeout config that I can set?)

edit: Forgot to say thank you.

Thank you :)

@mmedenjak
Copy link
Contributor

@mmedenjak mmedenjak commented Oct 4, 2018

Hi @LoneGumMan !

Happy to hear that. The fix releases the resources when we detect that the client has disconnected. We don't retain the resources for any longer than that and there is no timeout. One other reason that I can think of why the memory usage might still keep increasing until some point is that the GC will delay collecting the unreachable objects until it needs to. You may try tuning the GC to "kick in" somewhat earlier but I don't think this is strictly necessary as the overhead of running GC often might not be worth it.

Closing the issue then as it has been resolved. If you encounter an another problem, please open a new issue. Happy hazelcasting!

@mmedenjak mmedenjak closed this Oct 4, 2018
@mmedenjak mmedenjak removed the To Triage label Oct 4, 2018
@LoneGumMan
Copy link
Author

@LoneGumMan LoneGumMan commented Oct 4, 2018

I have the system hooked up to JVisualVM, and I am manually triggering GC and monitoring the GC log; it takes a few click, in the span of about 1 minute, for the heap to shrink to baseline in one big jump, not a gradual release.

That is the reason why I think maybe there is a timeouts, say a timeout before the disconnect is detected / confirmed and housekeeping happens.

Either way, it's no big deal, more or a curiosity than anything.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Projects
None yet
Linked pull requests

Successfully merging a pull request may close this issue.

None yet
9 participants
You can’t perform that action at this time.