Hono: Possible memory leak with `TelemetrySenderImpl`

[ctron]

While testing Hono I stumbled over the situation that the Hono HTTP adapter runs into memory issues. Peeking at the heap I can see a high number of instances of the TelemetrySenderImpl:

~~~
sh-4.2$ jmap -histo 1 | head -n 30

num #instances #bytes class name

1: 306888 31552608 [B
2: 273952 26299392 org.apache.qpid.proton.engine.impl.DeliveryImpl
3: 343058 25441536 [C
4: 273952 8766464 org.apache.qpid.proton.engine.impl.TransportDelivery
5: 330609 7934616 java.lang.String
6: 273952 6574848 io.vertx.proton.impl.ProtonDeliveryImpl
7: 273309 6559416 org.eclipse.hono.client.impl.TelemetrySenderImpl$$Lambda$180/1997786804
8: 284584 4553344 org.apache.qpid.proton.amqp.UnsignedInteger
9: 16953 3474568 [I
10: 14247 1534456 [Ljava.lang.Object;
11: 7507 834672 java.lang.Class
12: 19613 627616 java.util.concurrent.ConcurrentHashMap$Node
13: 8313 532032 java.nio.DirectByteBuffer
14: 10630 510240 java.nio.HeapByteBuffer
15: 5433 378288 [Ljava.util.HashMap$Node;
16: 10935 349920 java.util.HashMap$Node
17: 7718 308720 java.util.LinkedHashMap$Entry
18: 17963 287408 java.lang.Object
19: 386 212272 [Ljava.nio.channels.SelectionKey;
20: 4170 200160 io.netty.buffer.UnpooledByteBufAllocator$InstrumentedUnpooledUnsafeHeapByteBuf
21: 2186 192368 java.lang.reflect.Method
22: 3421 191576 java.util.LinkedHashMap
23: 133 177968 [Ljava.util.concurrent.ConcurrentHashMap$Node;
24: 3654 175392 java.util.HashMap
25: 4221 168840 io.netty.handler.codec.DefaultHeaders$HeaderEntry
26: 234 153504 io.netty.util.internal.shaded.org.jctools.queues.MpscArrayQueue
27: 4769 152608 java.lang.ref.WeakReference
~~~

Looking at the code I spotted the following in org.eclipse.hono.client.impl.HonoClientImpl.getOrCreateSender(String, Consumer<Handler<AsyncResult<MessageSender>>>, Handler<AsyncResult<MessageSender>>):

~~~java
…
} else if (!creationLocks.computeIfAbsent(key, k -> Boolean.FALSE)) {

// register a handler to be notified if the underlying connection to the server fails
// so that we can fail the result handler passed in
final Handler connectionFailureHandler = connectionLost -> {
// remove lock so that next attempt to open a sender doesn't fail
creationLocks.remove(key);
resultHandler.handle(Future.failedFuture(
new ServerErrorException(HttpURLConnection.HTTP_UNAVAILABLE, "connection to server lost")));
};
creationRequests.add(connectionFailureHandler);
creationLocks.put(key, Boolean.TRUE);
LOG.debug("creating new message sender for {}", key);
…
~~~

To me it looks like as if this method gets called un-synchronized from various threads. So between the "computeIfAbsent" (which will always return false) and the "put", it might be that multiple callers might have triggered a new connection.

Changing it to creationLocks.putIfAbsent(key, k -> Boolean.TRUE) == null should fix this issue as only the first caller will pass. After that the result will be non-null until the key is removed by the call to remove. Of course that would change the meaning of the value carried by the map. So maybe switching this to Map<String,Object> would be more appropriate then.

[sophokles73]

Well, to me the heap looks like there are many instances of a lambda expression that is part of TelemetrySenderImpl. What makes you believe that it is related to getting the sender? I would assume that the lambda expression instances are the ones created by the sendMessage method for processing the delivery update of a message sent downstream. Is there some way to identify the lambda precisely?

[ctron]

Yea, you are right. I just wanted to correct myself on that. It looks like this one growing over time:

~
sh-4.2$ jmap -histo 1 | grep 'org.eclipse.hono.client.impl.TelemetrySenderImpl$$Lambda$178'
7: 275506 6612144 org.eclipse.hono.client.impl.TelemetrySenderImpl$$Lambda$178/265457211
sh-4.2$ jmap -histo 1 | grep 'org.eclipse.hono.client.impl.TelemetrySenderImpl$$Lambda$178'
7: 276420 6634080 org.eclipse.hono.client.impl.TelemetrySenderImpl$$Lambda$178/265457211
sh-4.2$ jmap -histo 1 | grep 'org.eclipse.hono.client.impl.TelemetrySenderImpl$$Lambda$178'
7: 277204 6652896 org.eclipse.hono.client.impl.TelemetrySenderImpl$$Lambda$178/265457211
sh-4.2$ jmap -histo 1 | grep 'org.eclipse.hono.client.impl.TelemetrySenderImpl$$Lambda$178'
7: 278222 6677328 org.eclipse.hono.client.impl.TelemetrySenderImpl$$Lambda$178/265457211
sh-4.2$ jmap -histo 1 | grep 'org.eclipse.hono.client.impl.TelemetrySenderImpl$$Lambda$178'
7: 281062 6745488 org.eclipse.hono.client.impl.TelemetrySenderImpl$$Lambda$178/265457211
sh-4.2$ jmap -histo 1 | grep 'org.eclipse.hono.client.impl.TelemetrySenderImpl$$Lambda$178'
7: 324667 7792008 org.eclipse.hono.client.impl.TelemetrySenderImpl$$Lambda$178/265457211
sh-4.2$ jmap -histo 1 | grep 'org.eclipse.hono.client.impl.TelemetrySenderImpl$$Lambda$178'
7: 325330 7807920 org.eclipse.hono.client.impl.TelemetrySenderImpl$$Lambda$178/265457211
sh-4.2$ jmap -histo 1 | grep 'org.eclipse.hono.client.impl.TelemetrySenderImpl$$Lambda$178'
7: 326039 7824936 org.eclipse.hono.client.impl.TelemetrySenderImpl$$Lambda$178/265457211
~

[ctron]

Still I think here is a race condition with the "computeIfAbsent" construct. It might actually never manifest in an error, as, from what I've seen now, this method only gets called from one thread. At least in the HTTP adapter.

I will try to find out which lambda expression this is.

[sophokles73]

It might actually never manifest in an error, as, from what I've seen now, this method only gets called from one thread.

Well, that is the guarantee that vert.x provides if you are running in a Verticle. There will always be only a single thread (actually the same one) at a time executing the code.

[ctron]

Yes, but to me it looks like as if the HonoClientImpl doesn't enforce this. So for the HTTP adapter that will work, but any other use that is not enforced.

If however that would be enforced then this wouldn't need to be a ConcurrentHashMap either. But then the getOrX methods should be wrapped by vertx.runOnContext?!

[ctron]

Back to original issue. The leaked instance is indeed the handler to sender.send() in org.eclipse.hono.client.impl.TelemetrySenderImpl.sendMessage(Message).

It seems that the message it not settled locally. Settling the message locally seems to fix the issue.

[sophokles73]

It seems that the message it not settled locally. Settling the message locally seems to fix the issue.

You mean explicitly invoking ProtonDelivery.settle() once we're done handling the disposition received from the peer?

[sophokles73]

Oh, I see it in your code ... would you mind creating a PR? I think we also need to fix this in EventSenderImpl.

[ctron]

Done: https://github.com/eclipse/hono/pull/455

I initially forgot about the EventSenderImpl. Fixed that.

[sophokles73]

Yes, but to me it looks like as if the HonoClientImpl doesn't enforce this. So for the HTTP adapter that will work, but any other use that is not enforced.
If however that would be enforced then this wouldn't need to be a ConcurrentHashMap either. But then the getOrX methods should be wrapped by vertx.runOnContext?!

I think you are right in that we should probably change the gotOrCreate methods to run on the Context.

[sophokles73]

@ctron, can you please close this issue if you think that it has been fixed by your PR?
Thanks for contributing :+1:

[ctron]

The memory leak is fixed and I just created PR #461 for switching to auto-settle.