Subject: QueueServer crashing on antcntl

Starting on ~Feb 26, control of antennas would be lost once every ~3-6 hours. I tracked the issue down to the QueueServer on antcntl and the following:

Exception in thread "dispatch" java.lang.OutOfMemoryError: unable to create new native thread
	at java.lang.Thread.start0(Native Method)
	at java.lang.Thread.start(Thread.java:640)
		at jsda.QueueServer.NotifyOrCreateWorker(QueueServer.java:679)
	at jsda.QueueServer.DispatchThreadRun(QueueServer.java:565)
	at jsda.QueueServer.run(QueueServer.java:485)
	at java.lang.Thread.run(Thread.java:662)

The QueueServer would continue running but would not be able to respond to new JSDA packet connections.  To "fix" it, I would kill -15 <PID of QueueServer> directly.  Only to have the QueueServer run out of memory again with 3-6 hours.

Going through the SVN logs, I could find no changes that related to the JSDA classes used heavily by QueueServer, nor QueueServer.java itself for 3-12 months.

This started happening around the time of a series of power failures to the site yet there seemed to be no related hardware issue that I could find on antcntl or other JSDA connected hosts.

My initial suspicion was that some extra traffic was passing through antcntl on the JSDA network, keeping the QueueServer from being able to reclaim memory fast enough using incremental GC. I initially spent the day of Feb 27th adding the ability to write out all of the raw packets to /dev/shm so that I could capture the full packet log and process it after it crashed.  I also added -Xmx500m to the startup of QueueServer to increase its available allocatable memory under the JVM.  There has been some work done on the SonATABackend server, but, from what I could tell, should not be related to this issue.

While I let QueueServer run again to collect the packet log, it did take longer (~8hrs) before QueueServer ran out of memory again.  Before starting it I also added

-Dcom.sun.management.jmxremote

to the startup, allowing me to attach to the JVM using memory and resource tracking tools such as jmap, hat (later named jhat in JVM 6) and jconsole.

This allowed me to get an instantaneous view of the resource use for this running copy of QueueServer.  Based on the initial memory allocation view using these tools, I became convinced that the issue really was related to a memory leak of some kind.  I've been following the improvements to the JVM that came in version 6 and since the QueueServer itself does not instantiate the objects it passes as packets, I decided to use the JVM6 to run the QueueServer, which also allowed me to use jvisualvm, a much more responsive and useful resource tracking tool.

Using jvisualvm, I did track down a few slow memory leaks immediately and plugged them, however, memory was still being leaked and the QueueServer would crash after ~6-8 hours.  Mean while, I was editing a new tool that could help process the raw packet log, but initial examinations did not immediately show some extra bump in traffic that might be leading to this behavior.

Paying attention to memory generational allocations (eden, tenured and perm) and noticed that it appeared much of the memory allocated during regular packet passing operations was not being GC'd during the "minor" GC events.  This indicated that much of the memory was being passed into the older generation or tenured, which would keep it around until a full GC event.  Even then the full GC events were showing a gradual memory leak that would culminate in the out of memory exception.

This brings us to Mar 1st.  I began switching to different GC algorithms, settling on ParallelGC (better when using multi-core systems) and tuned the initial memory foot print with

-Xmx600M -Xms100M

This seemed to work well for ~6-9 hours, but still showed a general leak.

I spent most of Mar 2nd adding in more aggressive object handling in Server.java and QueueServer.java forcing more ObjectOutputStream resets and a few attempts at closing ObjectOutputStream and ObjectInputStream objects after handling 20K packets and then re-instantiating them (these streams are inherently leaky by design and require resets at least).

During the afternoon of Mar 2nd, I switched from allocating 100M minimum and tried allocating 300M minimum (this is used as "eden" space, there is a bit of trickiness here as major GC events may require double the eden space to handle transitioning eden space objects to the tenured space).  This caused the failure to occur much sooner (~20minutes), even though there was plenty of memory available (max usage was 50M, with a fall down to ~4-5MB after each minor GC event, the low end would gradually rise to over 20M).  This GC algorithm will allow real heap usage to grow to ~25% of the eden space and then do a minor GC.  I'd post plots of all of this but I haven't been recording them off of jvisualvm.

Currently, I have removed the minimum allocation entirely and the current behavior is much improved.  The initial eden space is ~8M, and the differences between peaks and dips in the minor GC events is strikingly different, maxing out at ~6.5M and dropping down to 2.5-3M.  There does still appear to be an upward trend, but it is vastly reduced from the rate that was leading to crashes over the last 4 days.  After 2.5 hours of monitoring, it appears that the heap usage floor increased from ~2.5M to ~3.2M.  If this trend continues, then the QueueServer will run out of memory in ~2100+ hours or ~89 days.  One issue with this is that GC events happen much more often and could potentially affect overall packet throughput.  However, the parallel nature of the GC handling should help mitigate this and it does not seem to have caused problems so far.

I have collected about a dozen heap maps and used the Eclipse Memory Analyzer to try to discover what is actually being leaked, this lead me to the Object related streams above and also to jsda.Connection, however, I have not been able to determine exactly where in jsda.Connection is related to this.  Also, jsda.Connection came up as about the 3rd order leak potential after I added resets per above.  It may account for the .28M/hr of leaking that I found in the last 2.5 hours.