RMI Activity Threads Lock GC o/p

[Keith Holdaway]

We are running into issues where ostensibly the memory management appears OK; less than 1% of the tome is in GC - when I put this file into HPJmeter 3.1;

0.000: [ParNew 47626K->6985K(1883840K), 0.5939434 secs]
0.613: [Full GC 6985K->6940K(1883840K), 0.7510576 secs]
288.169: [ParNew 399516K->20399K(1883840K), 3.0827681 secs]
844.451: [ParNew 412975K->26162K(1883840K), 0.3202843 secs]
1491.991: [ParNew 418738K->31914K(1883840K), 0.2347086 secs]
2177.292: [ParNew 424490K->37760K(1883840K), 0.3079626 secs]
2855.229: [ParNew 430336K->43595K(1883840K), 2.0764301 secs]
3575.979: [ParNew 436171K->49438K(1883840K), 0.2961466 secs]
3606.470: [ParNew 69808K->49730K(1883840K), 0.0388510 secs]
3606.511: [Full GC 49730K->42771K(1883840K), 2.5417084 secs]
4292.023: [ParNew 435347K->48662K(1883840K), 0.2445446 secs]
4970.650: [ParNew 441238K->54506K(1883840K), 0.2373110 secs]
5677.603: [ParNew 447082K->60349K(1883840K), 0.3322904 secs]
6367.994: [ParNew 452925K->66188K(1883840K), 0.2645763 secs]
7055.852: [ParNew 458764K->72033K(1883840K), 0.8281927 secs]
7210.009: [ParNew 167469K->73442K(1883840K), 0.0969525 secs]
7210.109: [Full GC 73442K->41123K(1883840K), 2.1642088 secs]
7909.604: [ParNew 433699K->47011K(1883840K), 0.2533163 secs]
8603.519: [ParNew 439587K->52863K(1883840K), 0.2230794 secs]
9289.216: [ParNew 445439K->58709K(1883840K), 0.2359698 secs]
9968.793: [ParNew 451285K->64554K(1883840K), 0.2656911 secs]
10649.694: [ParNew 457130K->70393K(1883840K), 0.2243246 secs]
10813.028: [ParNew 158599K->71696K(1883840K), 0.0770400 secs]
10813.107: [Full GC 71696K->41024K(1883840K), 1.7410828 secs]
11503.339: [ParNew 433600K->46907K(1883840K), 0.2542805 secs]
12191.022: [ParNew 439483K->52751K(1883840K), 0.2257059 secs]
12864.793: [ParNew 445327K->58591K(1883840K), 0.2231573 secs]
13546.217: [ParNew 451167K->64433K(1883840K), 0.2532376 secs]
14247.570: [ParNew 457009K->70278K(1883840K), 0.2111731 secs]
14415.581: [ParNew 168788K->71740K(1883840K), 0.0916532 secs]
14415.675: [Full GC 71740K->41182K(1883840K), 1.7439608 secs]
15096.989: [ParNew 433758K->47062K(1883840K), 0.2752132 secs]
15777.472: [ParNew 439638K->52905K(1883840K), 0.2132059 secs]
16475.184: [ParNew 445481K->58750K(1883840K), 0.2249407 secs]
16956.572: [ParNew 451326K->66543K(1883840K), 0.2237252 secs]
17593.401: [ParNew 459119K->72857K(1883840K), 0.2493865 secs]
18018.152: [ParNew 313587K->76412K(1883840K), 0.1719212 secs]
18018.326: [Full GC 76412K->44673K(1883840K), 1.9000112 secs]
18734.462: [ParNew 437249K->50542K(1883840K), 0.2459797 secs]
19434.180: [ParNew 443118K->56364K(1883840K), 0.2399764 secs]
20026.580: [ParNew 448940K->63103K(1883840K), 0.2327731 secs]
20723.692: [ParNew 455679K->68869K(1883840K), 0.2299928 secs]
21338.875: [ParNew 461445K->74742K(1883840K), 0.2005874 secs]
21620.952: [ParNew 269312K->78103K(1883840K), 0.1174351 secs]
21621.072: [Full GC 78103K->45998K(1883840K), 1.8386129 secs]
22227.195: [ParNew 438574K->51330K(1883840K), 0.2042002 secs]
22696.526: [ParNew 443906K->58015K(1883840K), 0.2154086 secs]
23246.252: [ParNew 450591K->63639K(1883840K), 0.2171688 secs]
23936.816: [ParNew 456215K->69353K(1883840K), 0.2421265 secs]
24529.163: [ParNew 461929K->75718K(1883840K), 0.1985638 secs]
25062.082: [ParNew 468294K->82472K(1883840K), 0.2119384 secs]
25223.640: [ParNew 205230K->84729K(1883840K), 0.0745738 secs]
25223.717: [Full GC 84729K->52981K(1883840K), 1.9445841 secs]
25808.453: [ParNew 445557K->58730K(1883840K), 0.2220857 secs]
27012.025: [ParNew 450888K->65873K(1883840K), 0.1835305 secs]
28826.400: [ParNew 194359K->68617K(1883840K), 0.0476450 secs]
28826.450: [Full GC 68617K->33933K(1883840K), 1.3288466 secs]
31626.367: [ParNew 426509K->39131K(1883840K), 0.1329507 secs]
32428.552: [ParNew 79650K->40294K(1883840K), 0.0451805 secs]
32428.600: [Full GC 40294K->29329K(1883840K), 1.0458070 secs]
36030.356: [ParNew 157110K->31764K(1883840K), 0.1066607 secs]
36030.465: [Full GC 31764K->28476K(1883840K), 0.9791810 secs]
39632.163: [ParNew 96572K->30448K(1883840K), 0.0852053 secs]
39632.251: [Full GC 30448K->27232K(1883840K), 0.9056725 secs]
43233.856: [ParNew 215673K->31439K(1883840K), 0.2064516 secs]
43234.074: [Full GC 31439K->28437K(1883840K), 1.1075595 secs]
46835.908: [ParNew 302993K->39167K(1883840K), 0.1579830 secs]
46836.074: [Full GC 39167K->35187K(1883840K), 1.1977157 secs]
50437.975: [ParNew 233401K->40095K(1883840K), 0.1419100 secs]
50438.130: [Full GC 40095K->36165K(1883840K), 1.3757682 secs]
54040.209: [ParNew 47288K->36927K(1883840K), 2.4154908 secs]
54042.656: [Full GC 36927K->35142K(1883840K), 1.7857094 secs]
57645.546: [ParNew 48404K->36028K(1883840K), 0.9233543 secs]
57646.503: [Full GC 36028K->33941K(1883840K), 1.2575880 secs]
61248.475: [ParNew 62613K->36158K(1883840K), 1.5358356 secs]
61250.042: [Full GC 36158K->34806K(1883840K), 1.1270633 secs]
64852.138: [ParNew 89705K->37904K(1883840K), 2.8467706 secs]
64855.019: [Full GC 37904K->36625K(1883840K), 1.2928314 secs]

Here are our VM args:

-server -Xms1840m -Xmx1840m -Xss256k -XX:+UseConcMarkSweepGC -XX:NewSize=384m -XX:MaxNewSize=384m -XX:PermSize=256m -XX:MaxPermSize=256m -Dsun.rmi.dgc.client.gcInterval=3600000 -Dsun.rmi.dgc.server.gcInterval=3600000
-Djava.headless.awt=true -Xloggc:gc.log

We see the DGC working every hour - 3600 seconds apart a ParNew followed by a Full GC - and there is a plethora of class unloading of the Sun reflection classes since we do a lot of RMI - serialisation/deserialisation.

Should we increase the frequency of DGC? Not sure why the VM hangs - possibly our client code - but we wanted to exclude completely the idea that GC is culpable of creating this or contributing to this failure.

thanks

keith