Negative Desired survivor size in GC Logs

Question

I am working on an in memory database completely written in Java. We have an input source which feeds the system with the data, this is the Extraction/Load phase. While running this I noticed the JVM was hanging, the underlying cause was Full GC's getting triggered. The application was then freezing, followed by an OutOfMemory error (GC Overhead Limit Exceeded)

Inspecting the GC logs revealed a lot of garbage collections both young and old. One thing that was surprising was the Desired Survivor size was negative. I am trying to understand why this is so? Has anyone encountered this before?

Environment:

• Windows7 Professional Service Pack1
• Dell Precision T7500, 24 cores
• 64 bit O/S 192 GB RAM

Sun JDK version: 1.7.0_13-b20 (64 bit)

JVM settings:

• -Xmx100g
• -Xms100g
• -verbose:gc
• -Xloggc:C:/temp/logs/gc.log
• -XX:+PrintGCTimeStamps
• -XX:+PrintGCDetails
• -XX:+PrintTenuringDistribution
• -XX:MaxPermSize=256m
• -XX:+UseParallelOldGC

GC Log Excerpt(This is not the full log):

0.666: [GC Desired survivor size 178913280 bytes, new threshold 7 (max 15) [PSYoungGen: 524289K->4431K(30583488K)] 524289K->4503K(100488576K), 0.0052536 secs] [Times: user=0.03 sys=0.00, real=0.01 secs]

0.671: [Full GC (System) [PSYoungGen: 4431K->0K(30583488K)] [ParOldGen: 72K->4096K(69905088K)] 4503K->4096K(100488576K) [PSPermGen: 8852K->8847K(21248K)], 0.0853597 secs] [Times: user=0.08 sys=0.00, real=0.09 secs]

12.306: [GC Desired survivor size 178913280 bytes, new threshold 7 (max 15) [PSYoungGen: 26214464K->389676K(30583488K)] 26218560K->393868K(100488576K), 0.1907519 secs] [Times: user=0.69 sys=0.69, real=0.19 secs]

19.845: [GC Desired survivor size 178913280 bytes, new threshold 7 (max 15) [PSYoungGen: 26604140K->4369012K(30583488K)] 26608334K->4539738K(100488576K), 2.0671426 secs] [Times: user=12.67 sys=10.64, real=2.07 secs]

31.930: [GC Desired survivor size 178913280 bytes, new threshold 7 (max 15) [PSYoungGen: 30583476K->4368998K(30583488K)] 30764447K->5793376K(100488576K), 2.4316614 secs] [Times: user=14.32 sys=12.07, real=2.43 secs]

43.950: [GC Desired survivor size 178913280 bytes, new threshold 7 (max 15) [PSYoungGen: 30583462K->4369018K(30583488K)] 32008283K->10474103K(100488576K), 3.0868838 secs] [Times: user=31.76 sys=10.64, real=3.09 secs]

57.851: [GC Desired survivor size -954466304 bytes, new threshold 6 (max 15) [PSYoungGen: 30583482K->4369011K(16019904K)] 36688571K->19053916K(85924992K), 5.0616910 secs] [Times: user=45.58 sys=21.95, real=5.06 secs]

67.849: [GC Desired survivor size -954466304 bytes, new threshold 5 (max 15) [PSYoungGen: 16019891K->7854065K(23301696K)] 30706222K->22540396K(93206784K), 1.9574226 secs] [Times: user=35.38 sys=0.00, real=1.96 secs]

74.940: [GC Desired survivor size -954466304 bytes, new threshold 4 (max 15) [PSYoungGen: 19504945K->11650800K(23301696K)] 34191281K->27450594K(93206784K), 3.2089939 secs] [Times: user=54.41 sys=1.51, real=3.21 secs]

83.683: [GC Desired survivor size -954466304 bytes, new threshold 3 (max 15) [PSYoungGen: 23301680K->11650785K(23301696K)] 39101518K->32434323K(93206784K), 4.8105989 secs] [Times: user=65.82 sys=10.30, real=4.81 secs]

93.647: [GC Desired survivor size -954466304 bytes, new threshold 2 (max 15) [PSYoungGen: 23301665K->10083445K(23301696K)] 44085203K->35191108K(93206784K), 3.9481522 secs] [Times: user=54.77 sys=8.02, real=3.95 secs]

102.406: [GC Desired survivor size -954466304 bytes, new threshold 1 (max 15) [PSYoungGen: 21734325K->10417779K(23301696K)] 46841988K->39667600K(93206784K), 4.7031362 secs] [Times: user=63.29 sys=9.50, real=4.70 secs]

112.109: [GC Desired survivor size -954466304 bytes, new threshold 1 (max 15) [PSYoungGen: 22068659K->5501380K(23301696K)] 51318480K->45289996K(93206784K), 5.6499475 secs] [Times: user=51.39 sys=23.81, real=5.65 secs]

122.858: [GC Desired survivor size -954466304 bytes, new threshold 1 (max 15) [PSYoungGen: 17152260K->5829244K(23301696K)] 56941300K->51036174K(93206784K), 3.9348524 secs] [Times: user=47.49 sys=11.48, real=3.93 secs]

132.599: [GC Desired survivor size -954466304 bytes, new threshold 1 (max 15) [PSYoungGen: 17480124K->4411050K(23301696K)] 62703442K->55124929K(93206784K), 3.2682313 secs] [Times: user=35.46 sys=10.86, real=3.27 secs]

141.869: [GC Desired survivor size -954466304 bytes, new threshold 1 (max 15) [PSYoungGen: 16061930K->5983419K(23301696K)] 66775809K->61080627K(93206784K), 3.1660854 secs] [Times: user=38.39 sys=9.45, real=3.17 secs]

149.996: [GC Desired survivor size -954466304 bytes, new threshold 1 (max 15) [PSYoungGen: 17634299K->5335607K(23301696K)] 72731507K->65656597K(93206784K), 4.4767380 secs] [Times: user=55.41 sys=12.67, real=4.48 secs]

154.473: [Full GC [PSYoungGen: 5335607K->0K(23301696K)] [ParOldGen: 60320990K->29187977K(69905088K)] 65656597K->29187977K(93206784K) [PSPermGen: 53148K->53088K(106560K)], 55.6080316 secs] [Times: user=518.19 sys=3.43, real=55.61 secs]

210.083: [GC Desired survivor size -954466304 bytes, new threshold 1 (max 15) [PSYoungGen: 1942K->96K(23301696K)] 29189919K->29188073K(93206784K), 0.0512343 secs] [Times: user=0.50 sys=0.00, real=0.05 secs]

210.134: [Full GC [PSYoungGen: 96K->0K(23301696K)] [ParOldGen: 29187977K->29187816K(69905088K)] 29188073K->29187816K(93206784K) [PSPermGen: 53088K->53087K(106624K)], 15.5128928 secs] [Times: user=236.31 sys=0.19, real=15.51 secs]

239.525: [GC Desired survivor size -954466304 bytes, new threshold 1 (max 15) [PSYoungGen: 11650880K->4622965K(23301696K)] 40838696K->33810782K(93206784K), 1.2739696 secs] [Times: user=23.01 sys=0.00, real=1.27 secs]

248.572: [GC Desired survivor size -954466304 bytes, new threshold 1 (max 15) [PSYoungGen: 16273845K->4009690K(23301696K)] 45461663K->37894227K(93206784K), 2.3307283 secs] [Times: user=41.84 sys=0.00, real=2.33 secs]

256.854: [GC Desired survivor size -954466304 bytes, new threshold 1 (max 15) [PSYoungGen: 15660570K->5707092K(23301696K)] 49545113K->43643553K(93206784K), 2.5595566 secs] [Times: user=46.05 sys=0.00, real=2.56 secs]

265.471: [GC Desired survivor size -954466304 bytes, new threshold 1 (max 15) [PSYoungGen: 17357972K->4996932K(23301696K)] 55294440K->48690372K(93206784K), 2.8941178 secs] [Times: user=52.21 sys=0.00, real=2.89 secs]

275.795: [GC Desired survivor size -954466304 bytes, new threshold 1 (max 15) [PSYoungGen: 16647812K->3781542K(23301696K)] 60342280K->52491436K(93206784K), 2.6240427 secs] [Times: user=47.18 sys=0.00, real=2.63 secs]

284.083: [GC Desired survivor size -954466304 bytes, new threshold 1 (max 15) [PSYoungGen: 15432422K->5815192K(23301696K)] 64142316K->58360954K(93206784K), 2.3724770 secs] [Times: user=42.68 sys=0.00, real=2.37 secs]

291.659: [GC Desired survivor size -954466304 bytes, new threshold 1 (max 15) [PSYoungGen: 17466072K->5357588K(23301696K)] 70011840K->63780322K(93206784K), 3.0063028 secs] [Times: user=54.20 sys=0.00, real=3.01 secs]

299.322: [GC Desired survivor size -1228210176 bytes, new threshold 2 (max 15) [PSYoungGen: 17008468K->6341939K(23301696K)] 75431206K->70078817K(93206784K), 4.1999305 secs] [Times: user=65.35 sys=5.13, real=4.20 secs]

303.523: [Full GC [PSYoungGen: 6341939K->0K(23301696K)] [ParOldGen: 63736877K->38098305K(69905088K)] 70078817K->38098305K(93206784K) [PSPermGen: 53125K->53125K(103360K)], 41.2081882 secs]

As you can notice at 57.851 seconds in the log above, we have a negative Desired survivor size, I am not sure why this is so?

Does this look like a memory leak?

Any help would be greatly appreciated. Also I am attaching a snapshot of visualvm for the heap

Answer 1

Yes, you problem appears to be that you just have too many live Objects. "GC Overhead Limit Exceeded" means GC ran, took a long time and freed very little. there are some knobs you can tweak to control the tresholds that controls that, but those will not help you to improve the performance.

I encountered the exact same problem when creating a memory intensive simulation (also 100 - 120GB max heap). My solution was to move away from Objects to store the data, and keep everything inside a primitive int[]. that worked ended up turning into a new open source project called Banana, which supports some primitive data structures. Banana actually is basing the data structures on it's own memory management, you get fully dynamic data structures without the overhead of objects. Go ahead and read the project wiki, it documents how things are working and got sample code and benchmarks.