Since upgrading to v6.1.5i3 (from v6.0.4) in conjunction with a major refactoring of our application we're seeing a large increase in memory usage. Where we were previously able to run with a 2.5GB heap we found we now need a 5GB heap. By our calculations memory usage is around 65MB/session. This is roughly 3x the ballpark figure given on the Memory Management page. Aside from our longer-term concerns over memory usage and our ability to scale up to handle more user sessions (currently we peak at 40 concurrent sessions) our immediate concern is tuning the JVM. Servoy does have a page on JVM tuning but it only covers the most basic settings.
Environment:
- CentOS 6 (64 bit)
- JDK 1.6.0_30 (64 bit)
- Servoy 6.1.5i3
Our first step was to increase the minimum and maximum heap size. We arrived at these final values through empirical testing:
- Code: Select all
# Initial Java Heap Size (in MB)
wrapper.java.initmemory=5000
# Maximum Java Heap Size (in MB)
wrapper.java.maxmemory=5000
Let's also capture a heapdump if/when we run out of memory so we can analyze it later:
- Code: Select all
wrapper.java.additional.5=-XX:+HeapDumpOnOutOfMemoryError
wrapper.java.additional.6=-XX:HeapDumpPath=%SERVOY_HOME%/log
Of course, things aren't quite so simple. With a larger heap size garbage collection pauses are now quite significant. How significant? About 10 seconds on our hardware. How do you monitor this? Add some more settings:
- Code: Select all
wrapper.java.additional.7=-Xloggc:%SERVOY_HOME%/log/jvm-gc-%WRAPPER_TIME_YYYYMMDDHHIISS%.log
wrapper.java.additional.8=-XX:+PrintGCDetails
wrapper.java.additional.9=-XX:+PrintGCDateStamps
# This setting is important so that the -Xloggc output filename specified above gets
# changed on a JVM restart, otherwise the previous log file will just get over-written!
wrapper.restart.reload_configuration=TRUE
The first thing we noticed when we started monitoring garbage collections was that the JVM was performing a full garbage collection exactly once an hour. Suspicious! It turns out these garbage collections are caused by RMI. By default, it triggers a full garbage collection once an hour. This can be fixed with a couple more settings (I believe Servoy ought to add this to their default configuration):
- Code: Select all
# by default rmi is triggering hourly full GCs. Change the interval to
# Long.MAX_VALUE - 1
wrapper.java.additional.10=-Dsun.rmi.dgc.server.gcInterval=9223372036854775806
wrapper.java.additional.11=-Dsun.rmi.dgc.client.gcInterval=9223372036854775806
At this point we've reduced the number of full garbage collections (and associated 10 second pauses) significantly but we're still seeing several collections per day during business hours. Since we have plenty of CPU to burn it looks like the Concurrent Mark Sweep collector would be a good choice since it trades off CPU usage and overall reduced garbage collection throughput in favour of reducing the required pauses.
- Code: Select all
# Reduce pauses when doing full GCs of the old gen...
wrapper.java.additional.12=-XX:+UseConcMarkSweepGC
wrapper.java.additional.13=-XX:+CMSClassUnloadingEnabled
After deploying this change we now see garbage collection pauses are generally under 1s with a few outliers taking up to 1.5s which is generally pretty good. Things aren't perfect however, we're still seeing the JVM fallback to the old-style stop-the-world garbage collection:
- Code: Select all
2013-06-17T23:32:10.982-0500: 540990.642: [GC 540990.642: [ParNew (promotion failed): 74077K->75407K(76672K), 0.0532440 secs]540990.695: [CMS: 3244591K->1893389K(5034816K), 14.9369580 secs] 3316776K->1893389K(5111488K), [CMS Perm : 147401K->145911K(200704K)], 14.9904340 secs] [Times: user=14.99 sys=0.01, real=14.98 secs]
It's not clear yet if the "ParNew (promotion failed)" errors are caused by heap memory fragmentation (something the CMS collector is susceptible to) or some other reason.
Has anyone else gone down this path already?
Thanks,
Corey