Proposed changes to the GC logging flags
Ciciora, Paul
Ciciora at cboe.com
Fri Apr 4 19:31:26 UTC 2008
I've been following the discussion and agree that it should not matter
what the format is if your PrintGC script shields us from it. That's
how it should be. I do recommend -XX:+PrintGCDateStamps over
+PrintGCTimeStamps. If you add this enhancement to 1.6.0_u4 and up
that's what I would want.
-----Original Message-----
From: hotspot-gc-dev-bounces at openjdk.java.net
[mailto:hotspot-gc-dev-bounces at openjdk.java.net] On Behalf Of
hotspot-gc-dev-request at openjdk.java.net
Sent: Friday, April 04, 2008 2:00 PM
To: hotspot-gc-dev at openjdk.java.net
Subject: hotspot-gc-dev Digest, Vol 10, Issue 5
Send hotspot-gc-dev mailing list submissions to
hotspot-gc-dev at openjdk.java.net
To subscribe or unsubscribe via the World Wide Web, visit
http://mail.openjdk.java.net/mailman/listinfo/hotspot-gc-dev
or, via email, send a message with subject or body 'help' to
hotspot-gc-dev-request at openjdk.java.net
You can reach the person managing the list at
hotspot-gc-dev-owner at openjdk.java.net
When replying, please edit your Subject line so it is more specific
than "Re: Contents of hotspot-gc-dev digest..."
Today's Topics:
1. Re: Proposed changes to the GC logging flags
(jamesnichols3 at gmail.com)
2. Re: Proposed changes to the GC logging flags
(jamesnichols3 at gmail.com)
3. Re: RMI Activity Threads Lock GC o/p (Y Srinivas Ramakrishna)
----------------------------------------------------------------------
Message: 1
Date: Fri, 4 Apr 2008 16:46:56 +0000
From: jamesnichols3 at gmail.com
Subject: Re: Proposed changes to the GC logging flags
To: "Tony Printezis" <tony.printezis at sun.com>
Cc: hotspot-gc-use at openjdk.java.net
Message-ID:
<1584721556-1207327612-cardhu_decombobulator_blackberry.rim.net-47129862
5- at bxe004.bisx.prod.on.blackberry>
Content-Type: text/plain; charset="us-ascii"
That would be sweet!
Jim
Sent from my Verizon Wireless BlackBerry
-----Original Message-----
From: Tony Printezis <tony.printezis at sun.com>
Date: Fri, 04 Apr 2008 12:43:01
To:James Nichols <jamesnichols3 at gmail.com>
Cc:Michael Finocchiaro
<michael.finocchiaro at gmail.com>,hotspot-gc-use at openjdk.java.net
Subject: Re: Proposed changes to the GC logging flags
James Nichols wrote:
> I'd rather not have the format of the log changed, but simplifying the
> arguments would be great. Isn't that the only change being proposed?
We're asking feedback on both.
> Doesn't everyone have a Perl script that they use to pull out the
> stuff from the log that's relevant and put it in gnuplot or Excel or
> something?
If we can provide you with a Java library that parses whatever format we
come up with and allows you to access the data from Java, in a sense
shielding you from GC log format changes, would that be a reasonable
compromise?
Tony
> On Fri, Apr 4, 2008 at 3:46 AM, Michael Finocchiaro
> <michael.finocchiaro at gmail.com <mailto:michael.finocchiaro at gmail.com>>
> wrote:
>
> That is good idea to make PGCTS the default with PGCD and I also
> agree that the TraceClassUnloading is annoying in a gc log.
>
> I would propose that you look at HP's JVM GC log format as
> something far easier to parse than the current format.
>
> http://docs.hp.com/en/5992-1918/ch01s25.html
>
> or perhaps the jstatd format.
>
> After about 5 or 6 years I can almost eyeball the current file
> format but a numeric based, space or comma-separated list of the
> GC cause and the memory space allocations would be a lot easier
> for post-mortem diagnosis and tuning. And, at least in the HP
> case, the overhead is very minimal (you get almost the same amount
> of detail as from -XX:+PrintTenuringDistribution in a single
> line)...and since there still is not a robust and easy-to-use
> equivalent of HPjmeter (disclosure - I worked for 10 years for HP)
> for analyzing the JavaSoft HotSpot JVMs, this would be an
improvement.
>
> My 2 cents,
> Fino
>
>
> On Thu, Apr 3, 2008 at 11:22 PM, Tony Printezis
> <tony.printezis at sun.com <mailto:tony.printezis at sun.com>> wrote:
>
> We're proposing a few small changes (and on significant one)
> to the way
> the GC logging flags work:
>
> a) When +PrintGCDetails is set, +PrintGCTimeStamps should be
> set by
> default (currently, it has to be set explicitly; what we've
> found is
> that it's always more useful to have the time stamps in a GC
> log when
> analyzing it)
> b) When -XXloggc: is set, +PrintGCDetails and
> +PrintGCTimeStamps are set
> automatically (instead of -verbosegc and +PrintGCTimeStamps)
> (again, for
> us, it's always more useful to have the more detailed
> +PrintGCDetails
> output in the log when analyzing it)
> c) When -verbosegc, +PrintGCDetails, or -Xloggc: are set,
> +TraceClassUnloading is _not_ automatically set, as it is now
(it
> polutes the output a bit during Full GCs)
>
> Notice that, for the above, you'll still be able to get the
> old behavior
> by setting / unsetting some flags; we're just trying to set
more
> sensible defaults.
>
> The more significant proposal:
>
> d) Eliminate the -verbosegc format in favor of the (more
> detailed and
> more useful, though less concise) +PrintGCDetails format. Do
> people
> still heavily use and rely on the -verbosegc format in a way
that
> migration to the +PrintGCDetails format will be difficult?
>
> Your thoughts and feedback on the above will be appreciated.
> Thank you,
>
> Tony, HS GC Group
>
> --
>
----------------------------------------------------------------------
> | Tony Printezis, Staff Engineer | Sun Microsystems Inc.
> |
> | | MS BUR02-311
> |
> | e-mail: tony.printezis at sun.com
> <mailto:tony.printezis at sun.com> | 35 Network Drive
> |
> | office: +1 781 442 0998 (x20998) | Burlington,
> MA01803-0902, USA |
>
----------------------------------------------------------------------
> e-mail client: Thunderbird (Solaris)
>
>
> _______________________________________________
> hotspot-gc-use mailing list
> hotspot-gc-use at openjdk.java.net
> <mailto:hotspot-gc-use at openjdk.java.net>
> http://mail.openjdk.java.net/mailman/listinfo/hotspot-gc-use
>
>
>
>
> --
> Michael Finocchiaro
> michael.finocchiaro at gmail.com
<mailto:michael.finocchiaro at gmail.com>
> Mobile Telephone: +33 6 67 90 64 39
> MSN: le_fino at hotmail.com <mailto:le_fino at hotmail.com>
> _______________________________________________
> hotspot-gc-use mailing list
> hotspot-gc-use at openjdk.java.net
> <mailto:hotspot-gc-use at openjdk.java.net>
> http://mail.openjdk.java.net/mailman/listinfo/hotspot-gc-use
>
>
--
----------------------------------------------------------------------
| Tony Printezis, Staff Engineer | Sun Microsystems Inc. |
| | MS BUR02-311 |
| e-mail: tony.printezis at sun.com | 35 Network Drive |
| office: +1 781 442 0998 (x20998) | Burlington, MA01803-0902, USA |
----------------------------------------------------------------------
e-mail client: Thunderbird (Solaris)
_______________________________________________
hotspot-gc-use mailing list
hotspot-gc-use at openjdk.java.net
http://mail.openjdk.java.net/mailman/listinfo/hotspot-gc-use
------------------------------
Message: 2
Date: Fri, 4 Apr 2008 17:59:18 +0000
From: jamesnichols3 at gmail.com
Subject: Re: Proposed changes to the GC logging flags
To: "Adam Hawthorne" <adamh at basis.com>,
hotspot-gc-use-bounces at openjdk.java.net,
hotspot-gc-use at openjdk.java.net
Message-ID:
<856414486-1207331960-cardhu_decombobulator_blackberry.rim.net-600871317
- at bxe004.bisx.prod.on.blackberry>
Content-Type: text/plain; charset="us-ascii"
I echo these sentiments. It would make it a lot easier to get
operations/IT types enable this. I don't know what it is, but they get
nervous when I ask to enable a bunch of arguments.
Jim
Sent from my Verizon Wireless BlackBerry
-----Original Message-----
From: Adam Hawthorne <adamh at basis.com>
Date: Fri, 4 Apr 2008 13:40:18
To:hotspot-gc-use at openjdk.java.net
Subject: Re: Proposed changes to the GC logging flags
We always require customers to enable the -XX:+PrintGCDetails and
PrintGCTimeStamps... making -verbose:gc do this by default would be a
welcome change for us. The -verbose:gc output is not helpful for us.
Thanks,
Adam
On Thu April 3 2008, Tony Printezis wrote:
> We're proposing a few small changes (and on significant one) to the
way
> the GC logging flags work:
>
> a) When +PrintGCDetails is set, +PrintGCTimeStamps should be set by
> default (currently, it has to be set explicitly; what we've found is
> that it's always more useful to have the time stamps in a GC log when
> analyzing it)
> b) When -XXloggc: is set, +PrintGCDetails and +PrintGCTimeStamps are
set
> automatically (instead of -verbosegc and +PrintGCTimeStamps) (again,
for
> us, it's always more useful to have the more detailed +PrintGCDetails
> output in the log when analyzing it)
> c) When -verbosegc, +PrintGCDetails, or -Xloggc: are set,
> +TraceClassUnloading is_not_ automatically set, as it is now (it
> polutes the output a bit during Full GCs)
>
> Notice that, for the above, you'll still be able to get the old
behavior
> by setting / unsetting some flags; we're just trying to set more
> sensible defaults.
>
> The more significant proposal:
>
> d) Eliminate the -verbosegc format in favor of the (more detailed and
> more useful, though less concise) +PrintGCDetails format. Do people
> still heavily use and rely on the -verbosegc format in a way that
> migration to the +PrintGCDetails format will be difficult?
>
> Your thoughts and feedback on the above will be appreciated. Thank
you,
>
> Tony, HS GC Group
>
--
Adam Hawthorne
Software Engineer
BASIS International Ltd.
www.basis.com
+1.505.345.5232 Phone
_______________________________________________
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
------------------------------
Message: 3
Date: Fri, 04 Apr 2008 11:10:21 -0700
From: Y Srinivas Ramakrishna <Y.S.Ramakrishna at Sun.COM>
Subject: Re: RMI Activity Threads Lock GC o/p
To: Michael Finocchiaro <michael.finocchiaro at gmail.com>
Cc: Keith Holdaway <Keith.Holdaway at sas.com>,
"hotspot-gc-use at openjdk.java.net"
<hotspot-gc-use at openjdk.java.net>
Message-ID: <f885bc391e.47f60c9d at sun.com>
Content-Type: text/plain; charset="us-ascii"
> 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
_______________________________________________
hotspot-gc-use mailing list
hotspot-gc-use at openjdk.java.net
http://mail.openjdk.java.net/mailman/listinfo/hotspot-gc-use
End of hotspot-gc-dev Digest, Vol 10, Issue 5
*********************************************
More information about the hotspot-gc-dev
mailing list