views:

815

answers:

5

Over the past year I've made huge improvements in my application's Java heap usage--a solid 66% reduction. In pursuit of that, I've been monitoring various metrics, such as Java heap size, cpu, Java non-heap, etc. via SNMP.

Recently, I've been monitoring how much real memory (RSS, resident set) by the JVM and am somewhat surprised. The real memory consumed by the JVM seems totally independent of my applications heap size, non-heap, eden space, thread count, etc.

Heap Size as measured by Java SNMP Java Heap Used Graph

Real Memory in KB. (E.g.: 1 MB of KB = 1 GB) Java Heap Used Graph

(The three dips in the heap graph correspond to application updates/restarts.)

This is a problem for me because all that extra memory the JVM is consuming is 'stealing' memory that could be used by the OS for file caching. In fact, once the RSS value reaches ~2.5-3GB, I start to see slower response times and higher CPU utilization from my application, mostly do to IO wait. As some point paging to the swap partition kicks in. This is all very undesirable.

So, my questions:

  • Why is this happening? What is going on "under the hood"?
  • What can I do to keep the JVM's real memory consumption in check?

The gory details:

  • RHEL4 64-bit (Linux - 2.6.9-78.0.5.ELsmp #1 SMP Wed Sep 24 ... 2008 x86_64 ... GNU/Linux)
  • Java 6 (build 1.6.0_07-b06)
  • Tomcat 6
  • Application (on-demand HTTP video streaming)
    • High I/O via java.nio FileChannels
    • Hundreds to low thousands of threads
    • Low database use
    • Spring, Hibernate

Relevant JVM parameters:

-Xms128m  
-Xmx640m  
-XX:+UseConcMarkSweepGC  
-XX:+AlwaysActAsServerClassMachine  
-XX:+CMSIncrementalMode    

-XX:+PrintGCDetails 
-XX:+PrintGCTimeStamps  
-XX:+PrintGCApplicationStoppedTime  
-XX:+CMSLoopWarn  
-XX:+HeapDumpOnOutOfMemoryError

How I measure RSS:

ps x -o command,rss | grep java | grep latest | cut -b 17-

This goes into a text file and is read into an RRD database my the monitoring system on regular intervals. Note that ps outputs Kilo Bytes.


The Problem & Solution*s*:

While in the end it was ATorras's answer that proved ultimately correct, it kdgregory who guided me to the correct diagnostics path with the use of pmap. (Go vote up both their answers!) Here is what was happening:

Things I know for sure:

  1. My application records and displays data with JRobin 1.4, something I coded into my app over three years ago.
  2. The busiest instance of the application currently creates
    1. Over 1000 a few new JRobin database files (at about 1.3MB each) within an hour of starting up
    2. ~100+ each day after start-up
  3. The app updates these JRobin data base objects once every 15s, if there is something to write.
  4. In the default configuration JRobin:
    1. uses a java.nio-based file access back-end. This back-end maps MappedByteBuffers to the files themselves.
    2. once every five minutes a JRobin daemon thread calls MappedByteBuffer.force() on every JRobin underlying database MBB
  5. pmap listed:
    1. 6500 mappings
    2. 5500 of which were 1.3MB JRobin database files, which works out to ~7.1GB

That last point was my "Eureka!" moment.

My corrective actions:

  1. Consider updating to the latest JRobinLite 1.5.2 which is apparently better
  2. Implement proper resource handling on JRobin databases. At the moment, once my application creates a database and then never dumps it after the database is no longer actively used.
  3. Experiment with moving the MappedByteBuffer.force() to database update events, and not a periodic timer. Will the problem magically go away?
  4. Immediately, change the JRobin back-end to the java.io implementation--a line line change. This will be slower, but it is possibly not an issue. Here is a graph showing the immediate impact of this change.

Java RSS memory used graph

Questions that I may or may not have time to figure out:

  • What is going on inside the JVM with MappedByteBuffer.force()? If nothing has changed, does it still write the entire file? Part of the file? Does it load it first?
  • Is there a certain amount of the MBB always in RSS at all times? (RSS was roughly half the total allocated MBB sizes. Coincidence? I suspect not.)
  • If I move the MappedByteBuffer.force() to database update events, and not a periodic timer, will the problem magically go away?
  • Why was the RSS slope so regular? It does not correlate to any of the application load metrics.
+4  A: 

RSS represents pages that are actively in use -- for Java, it's primarily the live objects in the heap, and the internal data structures in the JVM. There's not much that you can do to reduce its size except use fewer objects or do less processing.

In your case, I don't think it's an issue. The graph appears to show 3 meg consumed, not 3 gig as you write in the text. That's really small, and is unlikely to be causing paging.

So what else is happening in your system? Is it a situation where you have lots of Tomcat servers, each consuming 3M of RSS? You're throwing in a lot of GC flags, do they indicate the process is spending most of its time in GC? Do you have a database running on the same machine?

Edit in response to comments

Regarding the 3M RSS size - yeah, that seemed too low for a Tomcat process (I checked my box, and have one at 89M that hasn't been active for a while). However, I don't necessarily expect it to be > heap size, and I certainly don't expect it to be almost 5 times heap size (you use -Xmx640) -- it should at worst be heap size + some per-app constant.

Which causes me to suspect your numbers. So, rather than a graph over time, please run the following to get a snapshot (replace 7429 by whatever process ID you're using):

ps -p 7429 -o pcpu,cutime,cstime,cmin_flt,cmaj_flt,rss,size,vsize

(Edit by Stu so we can have formated results to the above request for ps info:)

[stu@server ~]$ ps -p 12720 -o pcpu,cutime,cstime,cmin_flt,cmaj_flt,rss,size,vsize
%CPU - - - -  RSS SZ  VSZ
28.8 - - - - 3262316 1333832 8725584

Edit to explain these numbers for posterity

RSS, as noted, is the resident set size: the pages in physical memory. SZ holds the number of pages writable by the process (the commit charge); the manpage describes this value as "very rough". VSZ holds the size of the virtual memory map for the process: writable pages plus shared pages.

Normally, VSZ is slightly > SZ, and very much > RSS. This output indicates a very unusual situation.

Elaboration on why the only solution is to reduce objects

RSS represents the number of pages resident in RAM -- the pages that are actively accessed. With Java, the garbage collector will periodically walk the entire object graph. If this object graph occupies most of the heap space, then the collector will touch every page in the heap, requiring all of those pages to become memory-resident. The GC is very good about compacting the heap after each major collection, so if you're running with a partial heap, there most of the pages should not need to be in RAM.

And some other options

I noticed that you mentioned having hundreds to low thousands of threads. The stacks for these threads will also add to the RSS, although it shouldn't be much. Assuming that the threads have a shallow call depth (typical for app-server handler threads), each should only consume a page or two of physical memory, even though there's a half-meg commit charge for each.

kdgregory
The GC times look OK. I continue to monitor them. Like I said, the io wait time is increasing. And I can see that the system file cache shrinks to a very small number, compared to when the JVM is not sucking up huge swaths of real memory.
Stu Thompson
The RSS value *is* 3GB, not 3MB. The graph is in Kilo Bytes. 3 mega of KB = 3GB. I will update question for clarity. (Besides, one would logically expect real memory to be > java heap size. 3MB is a fraction of 400MB.)
Stu Thompson
As you can seem by the `ps` output (edited into your answer), the 3GB number is accurate. (I started graphing over time after noticing large numbers from `top` and `ps` on long running instances.) It is what surprised me--something seems wrong if my RSS is 5 times the heap size. Hence this SO question.
Stu Thompson
A: 

Have you tried asking Dr. Click?

+6  A: 

Hi,

Just an idea: NIO buffers are placed outside the JVM.

Regards.

ATorras
Interesting. I do use the `java.nio.FileChannel` allot...must investigate...
Stu Thompson
+1 - although this should only be an issue for the files that are being actively accessed
kdgregory
An argument against this would be that **a)** the RSS graph has an amazingly regular, straight slope, and **b)** the `FileChannel` usage is tied to how busy the application is, which fluctuates wildly hour-to-hour, day-to-day. I would expect to see a correlation.
Stu Thompson
+1  A: 

The current garbage collector in Java is well known for not releasing allocated memory, although the memory is not required anymore. It's quite strange however, that your RSS size increases to >3GB although your heap size is limited to 640MB. Are you using any native code in your application or are you having the native performance optimization pack for Tomcat enabled? In that case, you may of course have a native memory leak in your code or in Tomcat.

With Java 6u14, Sun introduced the new "Garbage-First" garbage collector, which is able to release memory back to the operating system if it's not required anymore. It's still categorized as experimental and not enabled by default, but if it is a feasible option for you, I would try to upgrade to the newest Java 6 release and enable the new garbage collector with the command line arguments "-XX:+UnlockExperimentalVMOptions -XX:+UseG1GC". It might solve your problem.

jarnbjo
No JNI, but the application does rely heavily on `java.nio.FileChannel` to send data from disk to NIC...
Stu Thompson
And, yea, I've been wanting to update to 6u14 for Garbage-First. Soon...
Stu Thompson
And you are not using the native Tomcat functionaliy (http://tomcat.apache.org/tomcat-6.0-doc/apr.html)? Unless you are keeping references to a lot of open FileChannel objects (and this would cause other problems, like reaching the max number of open files allowed), FileChannel usage alone is not really an explanation of your applications behaviour.
jarnbjo
No, I'm not. **a)** is it is flaky on 64-bit Linux (or was last time I checked), **b)** I had issues with in an a 3rd party jar, and **c)** I really don't have that many connections per second to worry about connector performance.
Stu Thompson
+1  A: 

Why is this happening? What is going on "under the hood"?

JVM uses more memory than just the heap. For example Java methods, thread stacks and native handles are allocated in memory separate from the heap, as well as JVM internal data structures.

In your case, possible causes of troubles may be: NIO (already mentioned), JNI (already mentioned), excessive threads creation.

About JNI, you wrote that the application wasn't using JNI but... What type of JDBC driver are you using? Could it be a type 2, and leaking? It's very unlikely though as you said database usage was low.

About excessive threads creation, each thread gets its own stack which may be quite large. The stack size actually depends on the VM, OS and architecture e.g. for JRockit it's 256K on Linux x64, I didn't find the reference in Sun's documentation for Sun's VM. This impacts directly the thread memory (thread memory = thread stack size * number of threads). And if you create and destroy lots of thread, the memory is probably not reused.

What can I do to keep the JVM's real memory consumption in check?

To be honest, hundreds to low thousands of threads seems enormous to me. That said, if you really need that much threads, the thread stack size can be configured via the -Xss option. This may reduce the memory consumption. But I don't think this will solve the whole problem. I tend to think that there is a leak somewhere when I look at the real memory graph.

Pascal Thivent
**Threads:** My apps threads, specifically the threads that handle an HTTP connection, are frequently long lived: tens of seconds, minutes, or potentially longer. The number of connections my server can process at at once (the number of HTTP streams) is a linear function of how many threads I can have. In every day usage, like in the scope of above graphs, the number of threads varied between 50 and 700. An unusual application, yea.
Stu Thompson
**JNI:** Good point, I have no idea what type it is. But I'm not inclined to investigate just yet because, as you noted, my app is not DB intensive.
Stu Thompson
**Xss:** It is something I've considered, but it math does not points to this being an issue. Even with 1000 threads, at 256k each, we are still only at 256MB. More realistically, my app's thread stacks total 128MB. Neither value is close to the 3GB hole I have. Tinkering with `-Xss?` now would be premature optimization at best, random guessing at worst.
Stu Thompson
Anyway, thanks for the ideas. It does look like I'll find the issue in the 'real memory graph', which is a whole new world for me.
Stu Thompson
@Stu I agree with all points
Pascal Thivent