Memory utilisation grows way beyond the allocated JVM heap

[Neil Condon]

Hi,
I have been evaluating OpenTSDB for an IoT application.  My main aim was to benchmark write throughput, as a function JVM heap allocation:  just how many writes can I achieve; where are the bottlenecks?
My issue is that the JVM RAMutilisation is growing, despite the heap being under control.   I have allocated 3gb of heap (-Xmxs3g & -Xmxs3g), and I can track the heap utilisation using tcollector to look at 'tsd.jvm.ramfree' and 'tsd.jvm.ramused'.   'ramused' is a constant 3GB (as expected), and I can watch the depletion and recovery of 'ramfree' progress as writes come in that then the GC kicks in... all is stable.   A direct look at the GC logs confirm this.
However, over the course of several hours, 'top' tells me that '%MEM' for the JVM process climbes to well over 60% (4.8GB), until eventually /proc/meminfo/(MemAvailable) falls to zero (there are other processes running, of course) and the node collapses in a flurry of HDD/swap activity.
I have burst-written points repeatedly at over 150,000 writes/sec and as slow as ~1000 writes/sec through the telnet interface, in all cases the 3gb heap (and GC) holds up - it's this additional growth in overall RAM used that eventually kils the node.
What is causing the JVM to grow way beyond its heap size?
---
I am running OpenTSDB 2.1.3 from the RPM, on CentOS 7.0, OpenJDK 1.8.0_65-b17, with MapR-DB (5.0) and AsyncHbase 1.6.
The nodes are deliberately low-end:  dual-core G3240 with 8GB RAM.

Thanks,
N

[Nicholas Whitehead]

File handles ? How many open connections do have at peak memory ?

[Neil Condon]

That's a good thought!   By the looks of it... around 123,000   That's too many, right?

My test data scripts take files full of 'put' statements, which are synthesised elsewhere, and then pushes them into the telnet API.   Is this a particular weakness of the telnet API, or am I doing something dim that leaves a lot of connections active?

Tks,   N

[Neil Condon]

Beg your pardon.   There were 123,000 connection established in total, but there are only 5 or 6 open at the time the node runs out of RAM.

[Nicholas Whitehead]

Ah.... well, that's not that many :) Pulled the trigger too soon. Not to linger on file handles, but can you lsof the process at or near peak and see how many handles the OS thinks are open ?

On Wed, Apr 13, 2016 at 5:47 PM, 'Neil Condon' via OpenTSDB <open...@googlegroups.com> wrote:

Beg your pardon.   There were 123,000 connection established in total, but there are only 5 or 6 open at the time the node runs out of RAM.

[Neil Condon]

Yes, sure, but will have to be in the morning - node has just died an I'm not in the office to restart it.

Tks for the advice....

[Neil Condon]

I can't see any evidence of file handles growing out of control.   At startup the TSD holds 323.   By the time 2GB of RAM has gone 'missing', the number is fluctuating between 330 and 342.  This is consistent with tsd.connectionmgr.connections, which is telling me there are between 4 and 20 connections active.

[John A. Tamplin]

On Thu, Apr 14, 2016 at 4:44 AM, 'Neil Condon' via OpenTSDB <open...@googlegroups.com> wrote:

I can't see any evidence of file handles growing out of control.   At startup the TSD holds 323.   By the time 2GB of RAM has gone 'missing', the number is fluctuating between 330 and 342.  This is consistent with tsd.connectionmgr.connections, which is telling me there are between 4 and 20 connections active.

Note that memory allocated by native code and byte buffers are allocated off-heap.

--

John A. Tamplin

[Nicholas Whitehead]

Yeah, the NIO MXBean should show direct buffer allocated memory, but I thought that since most ( all ?) The Netty channel buffers in the tsd are heap based, there wouldn't be that many direct byte buffers.

[Neil Condon]

Yes - thanks:  I am learning as I go, but I had picked up that the heap was not the whole story.   To dig into this, I turned on Native Memory Tracking (-XX:NativeMemoryTracking=summary), so that I can study the output of 'jdmc <pid> VM.native_memory summary'.   None of the various categories (Heap, Class, Thread, Code, GC, Compiler, Internal, Symbol) are growing over the same period that I see the overall process RAM grow by >50%.   Does this mean that the leak is in native code somewhere?

[Neil Condon]

Based on advice from the MapR team, I have turned off TSD compactions, and that does seem to have stabilised things.   However, I still have reserved memory of 3.7GB for a -Xmx of only 2GB max heap.   Most of that seems to go in the 'Class' category.  I am writing about 22k points/sec with burst rates up to 195k.   Does that make sense?

(enc. the output of Native Memory Tracking.)

[Jonathan Creasy]

I've been writing millions of dp/s and do not see this behavior. Something is wrong for sure. 

Any chance you could swap out one of your write nodes with the 2.2 release? (or even better, the 2.3.0-SNAPSHOT in the next branch)

[Neil Condon]

Certainly willing to try.   2.2 requires asynchbase 1.7, is that right?

[Neil Condon]

Could a large class allocation be a consequence of a large number of UIDs?

[ManOLamancha]

On Friday, April 22, 2016 at 10:31:49 AM UTC-7, Neil Condon wrote:

Could a large class allocation be a consequence of a large number of UIDs?

Hiya, in general if the heap starts to blow up it's usually due to HBase regions splitting, moving or even the servers falling over. First check your logs for NSRE events and watch the TSD counters (/api/stats) for "tsd.hbase.nsre" to see if it increases. You can save the heap by dropping "hbase.nsre.high_watermark" to something small like "10" or so. That will fail the RPCs and you'll want to use a plugin for 2.2 to spool to disk or another queue till it can write to HBase again.

[Neil Condon]

Hi.   Thanks for the tip.

It's not the heap size which is growing - that's under control.   What I see is that the off-heap allocation grows over time.   By far the largest component of that is the "Class" category, according to the JVMs own Native Memory Tracking:   Class allocation (~1G) is roughly half the max heap size (~2G).   I'm wondering if this is linked to the size of the UID cache:  I have getting on for 500k UIDs?

Also I am on MapR-DB, not HBase - there are no "No Such Region Events" recorded by the TSDs, and this probably reflects that MapR-DB is lightning fast a region failover, splitting and compaction type activity.

I might have another use case for a spooling plug-in though...  do you know if such a plugin exists already?

[ManOLamancha]

On Friday, April 29, 2016 at 7:03:50 AM UTC-7, Neil Condon wrote:

Hi.   Thanks for the tip.

It's not the heap size which is growing - that's under control.   What I see is that the off-heap allocation grows over time.   By far the largest component of that is the "Class" category, according to the JVMs own Native Memory Tracking:   Class allocation (~1G) is roughly half the max heap size (~2G).   I'm wondering if this is linked to the size of the UID cache:  I have getting on for 500k UIDs?

The Class allocation is set by the JVM at startup. What settings are you passing in? Any -X overrides? Otherwise TSD is only using 21M of the class space, which sounds a little high but is probably fairly normal. The 500K UIDs would only be allocated on the heap and wouldn't affect the class space at all. 

 

Also I am on MapR-DB, not HBase - there are no "No Such Region Events" recorded by the TSDs, and this probably reflects that MapR-DB is lightning fast a region failover, splitting and compaction type activity.

Did you have to replace your AsyncHBase client with a MapR specified client? You should still see splits if using AsyncHBase as the only way it knows to write to a new region when it does split is via an NSRE. You may not be hitting splits yet though. 

 

I might have another use case for a spooling plug-in though...  do you know if such a plugin exists already?

I don't have one yet, though I started upstreaming a simple Kafka version at https://github.com/manolama/opentsdb-seh-kafka 

[Neil Condon]

Hi,

The JVM was started as follows:

root     10434     1 18 May04 ?        07:02:43 java -DLOG_FILE_PREFIX=/var/log/opentsdb/opentsdb-eddisc0- -enableassertions -enablesystemassertions -Xmx2g -XX:NativeMemoryTracking=summary -XX:OnOutOfMemoryError=/usr/share/opentsdb/tools/opentsdb_restart.py -classpath /usr/share/opentsdb/*.jar:/usr/share/opentsdb:/usr/share/opentsdb/bin:/usr/share/opentsdb/lib/async-1.4.0.jar:/usr/share/opentsdb/lib/asynchbase-1.7.0-mapr-1603.jar:/usr/share/opentsdb/lib/asynchbase-1.7.1.jar:/usr/share/opentsdb/lib/commons-collections-3.2.2.jar:/usr/share/opentsdb/lib/commons-configuration-1.6.jar:/usr/share/opentsdb/lib/commons-lang-2.6.jar:/usr/share/opentsdb/lib/commons-logging-1.1.3.jar:/usr/share/opentsdb/lib/commons-math3-3.4.1.jar:/usr/share/opentsdb/lib/guava-18.0.jar:/usr/share/opentsdb/lib/hadoop-auth-2.7.0-mapr-1602.jar:/usr/share/opentsdb/lib/hadoop-common-2.7.0-mapr-1602.jar:/usr/share/opentsdb/lib/jackson-annotations-2.4.3.jar:/usr/share/opentsdb/lib/jackson-core-2.4.3.jar:/usr/share/opentsdb/lib/jackson-databind-2.4.3.jar:/usr/share/opentsdb/lib/json-20080701.jar:/usr/share/opentsdb/lib/log4j-over-slf4j-1.7.7.jar:/usr/share/opentsdb/lib/logback-classic-1.0.13.jar:/usr/share/opentsdb/lib/logback-core-1.0.13.jar:/usr/share/opentsdb/lib/maprfs-5.1.0-mapr.jar:/usr/share/opentsdb/lib/mapr-hbase-5.1.0-mapr.jar:/usr/share/opentsdb/lib/netty-3.9.4.Final.jar:/usr/share/opentsdb/lib/protobuf-java-2.5.0.jar:/usr/share/opentsdb/lib/slf4j-api-1.7.7.jar:/usr/share/opentsdb/lib/tsdb-2.2.0.jar:/usr/share/opentsdb/lib/zookeeper-3.4.5.jar:/etc/opentsdb net.opentsdb.tools.TSDMain --config=/etc/opentsdb/opentsdb.conf

...you can see that I have -Xmx2g to (I think) fix the heap size, and I have turned Native Memory Tracking on with -XX:NativeMemoryTracking=summary.   The rest of the arguments are added by the init script that ships with the 2.2.0 RPM.

Your suspicion is right:  I've replaced various jars with those from the mapr-asynchbase-1.7.0 package.

Does that help at all?

N