RMI Activity Threads Lock GC o/p

Fri Apr 4 11:10:21 PDT 2008

> Can you explain how -XX:+CMSClassUnloadingEnabled is going to help? I
> haven't used that parameter before.

The idea is that, assuming concurrent collections happen, classes will be
unloaded (and perm gen cleaned) as a result of this flag, and will thus
make it unnecessary for a full gc to reclaim that storage. Sometimes, this
can have the beneficial effect of also cleaning up a bunch of storage in
non-perm heap which had been referenced from objects in the perm gen
which were no longer reachable, but which tended to act as "roots" keeping them
alive. It's a general prophylactic in this case, rather than specifically targeted at an issue
that Keith is seeing (which specific problem, as I indicated, I do not
quite fully understand yet from his original email).

-- ramki

> Thanks,
> Fino
> 
> On Fri, Apr 4, 2008 at 6:42 PM, Y Srinivas Ramakrishna <
> Y.S.Ramakrishna at sun.com> wrote:
> 
> >
> > Hi Keith --
> >
> > See inline below:-
> >
> > > 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]
> > >
> >
> > Did you notice that towards the end of the log above, your allocation
> > rates
> > have plummetted and the scavenges themselves are taking pretty long?
> > Perhaps that gives you some ideas as to what could be happening?
> >
> > > 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
> >
> > I'd suggest experimenting with either:-
> >
> > -XX:+ExplicitGCInvokesConcurrent[AndUnloadsClasses]
> > -XX:+CMSClassUnloadingEnabled
> >
> > or, perhaps less desirable, but certainly useful from the 
> prespective of
> > your
> > debugging objectives here:-
> >
> > -XX:+DisableExplicitGC -XX:+CMSClassUnloadingEnabled
> >
> > >
> > > 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.
> >
> > Check that you are not paging and running slow rather than hanging?
> >
> > When you get the "hung jvm", if on Solaris, try prstat -L -p <pid> 
> to see
> > if any threads are active, and also try pstack <pid> (perhaps several
> > seconds apart, to observe any active threads). If the application shows
> > no activity (from above), try jstack <pid> (or kill -QUIT <pid>) to
> > see if you can elicit a java thread stack dump.
> >
> > (I was not sure from yr description whether you believed the JVM was
> > hung or that the jvm was responding -- for example doing the occasional
> > gc etc -- but the application response had plummeted.)
> >
> > -- ramki
> >
> > >
> > > thanks
> > >
> > > keith
> > >
> > >
> > > _______________________________________________
> > > hotspot-gc-use mailing list
> > > hotspot-gc-use at openjdk.java.net
> > > http://mail.openjdk.java.net/mailman/listinfo/hotspot-gc-use
> > _______________________________________________
> > hotspot-gc-use mailing list
> > hotspot-gc-use at openjdk.java.net
> > http://mail.openjdk.java.net/mailman/listinfo/hotspot-gc-use
> >
> 
> 
> 
> -- 
> Michael Finocchiaro
> michael.finocchiaro at gmail.com
> Mobile Telephone: +33 6 67 90 64 39
> MSN: le_fino at hotmail.com
> _______________________________________________
> hotspot-gc-use mailing list
> hotspot-gc-use at openjdk.java.net
> http://mail.openjdk.java.net/mailman/listinfo/hotspot-gc-use