G1 issue: falling over to Full GC

Fri Nov 2 16:29:52 PDT 2012

To be honest, I didn't dig in yet as I got the set up running in our plant
towards the end of the day, and only casually looked at basic GC timestamps
for the full GCs.

We do use some weak refs (no soft/phantom though), but I wouldn't call it
heavy (or even medium) for that matter.  However, I'd have to look at what
GC reports, as you mention, to make sure, but I'm pretty confident that
it's not heavy. :)

The server is dedicated to this sole java process, and nothing else of
significance (mem or cpu) is running on there.

I'll try to investigate next week to see if anything sticks out.  Regular
old GC is sufficient for my use case now, so I'm merely trying to see if I
can get some really cheap gains purely by enabling the parallel collector.
:)

Generally speaking though, what sort of (ballpark) speedup is expected for
parallel old vs single threaded? Let's say on a machine with a modest CPU
count (8-16 hardware threads).  I'd imagine any contention would
significantly reduce the speedup factor for hugely parallel machines, but
curious about the modest space.  Are there any known issues/scenarios that
would nullify its benefit, other than what you've already mentioned?

Thanks for all the advice and info.

Sent from my phone
On Nov 2, 2012 7:14 PM, "Charlie Hunt" <chunt at salesforce.com> wrote:

> Do you have GC logs you could share?
>
> We probably are gonna need more info on what's going on within
> ParallelOld.   We might get some additional info from
>  +PrintGCTaskTimeStamps or +PrintParallelOldGCPhaseTimes.  I don't recall
> how intrusive they are though.  If you've got a lot of threads, we'll
> probably get a lot of data too.  But, hopefully there's something in there
> that lends a clue as to issue.  If there's contention, that suggests to me
> some contention in work stealing.  IIRC, there's a way to get work stealing
> info in +ParallelOld GC.  But, my mind is drawing a blank. :-|
>
> Just off the top of my head, do you know if this app makes heavy use of
> Reference objects, i.e. < Weak | Soft | Phantom | Final > References?
>
> Adding +PrintReferenceGC will tell us what kind of overhead you're
> experiencing with reference processing.  If you're seeing high values of
> reference processing, then you'll probably want to add
> -XX:+ParallelRefProcEnabled.
>
> I'd look at reference processing first before looking at the
> +PrintParallelOldGCPhaseTimes or +PrintGCTaskTimeStamps.
>
> Ooh, another thought, are there other Java apps running on the same
> system?  If so, how many GC threads and application threads tend to be
> active at any given time?
>
> hths,
>
> charlie ...
>
> On Nov 2, 2012, at 5:42 PM, Vitaly Davidovich wrote:
>
> Thanks Charlie.  At a quick glance, I didn't see it benefit my case today
> (~5gb old) - wall clock time was roughly same as single threaded, but user
> time was quite high (7 secs wall, 37 sec user).  This is on an 8 way Xeon
> Linux server.
>
> I seem to vaguely recall reading that parallel old sometimes performs
> worse than single threaded old in some cases, perhaps due to some
> contention between GC threads.
>
> Anyway, I'll keep monitoring though.
>
> Thanks
>
> Sent from my phone
> On Nov 2, 2012 10:15 AM, "Charlie Hunt" <chunt at salesforce.com> wrote:
>
>> Yes, I'd recommend +UseParallelOldGC on 6u23 even though it's not
>> auto-enabled.
>>
>> hths,
>>
>> charlie ...
>>
>> On Nov 2, 2012, at 8:04 AM, Vitaly Davidovich wrote:
>>
>> Hi Charlie,
>>
>> Out of curiosity, is UseParallelOldGC advisable on, say, 6u23? It's off
>> by default, as you say, until 7u4 so I'm unsure if that's for some
>> good/specific reason or not.
>>
>> Thanks
>>
>> Sent from my phone
>> On Nov 2, 2012 8:36 AM, "Charlie Hunt" <chunt at salesforce.com> wrote:
>>
>>> Jumping in a bit late ...
>>>
>>> Strongly suggest to anyone evaluating G1 to not use anything prior to
>>> 7u4.  And, even better if you use (as of this writing) 7u9, or the latest
>>> production Java 7 HotSpot VM.
>>>
>>> Fwiw, I'm really liking what I am seeing in 7u9 with the exception on
>>> one issue, (http://bugs.sun.com/bugdatabase/view_bug.do?bug_id=7143858),
>>> which is currently slated to be back ported to a future Java 7, (thanks
>>> Monica, John Cuthbertson and Bengt tackling this!).
>>>
>>> >From looking at your observations and others comments thus far, my
>>> initial reaction is that with a 1G Java heap, you might get the best
>>> results with -XX:+UseParallelOldGC.  Are you using -XX:+UseParallelGC, or
>>> -XX:+UseParallelOldGC?  Or, are you not setting a GC?  Not until 7u4 is
>>> -XX:+UseParallelOldGC automatically set for what's called "server class"
>>> machines when you don't specify a GC.
>>>
>>> The lengthy concurrent mark could be the result of the implementation of
>>> G1 in 6u*, or it could be that your system is swapping. Could you check if
>>> your system is swapping?  On Solaris you can monitor this using vmstat and
>>> observing, not only just free memory, but also sr == scan rate along with
>>> pi == page in and po == page out.  Seeing sr (page scan activity) along
>>> with low free memory along with pi & po activity are strong suggestions of
>>> swapping.  Seeing low free memory and no sr activity is ok, i.e. no
>>> swapping.
>>>
>>> Additionally, you are right.  "partial" was changed to "mixed" in the GC
>>> logs.  For those interested in a bit of history .... this change was made
>>> since we felt "partial" was misleading.  What partial was intended to mean
>>> was a partial old gen collection, which did occur.  But, on that same GC
>>> event it also included a young gen GC.  As a result, we changed the GC
>>> event name to "mixed" since that GC event was really a combination of both
>>> a young gen GC and portion of old gen GC.
>>>
>>> Simone also has a good suggestion with including -XX:+PrintFlagsFinal
>>> and -showversion as part of the GC log data to collect, especially with G1
>>> continuing to be improve and evolve.
>>>
>>> Look forward to seeing your GC logs!
>>>
>>> hths,
>>>
>>> charlie ....
>>>
>>> On Nov 2, 2012, at 5:46 AM, Andreas Müller wrote:
>>>
>>> > Hi Simone,
>>> >
>>> >> 4972.437: [GC pause (partial), 1.89505180 secs]
>>> >> that I cannot decypher (to Monica - what "partial" means ?), and no
>>> mixed GCs, which seems unusual as well.
>>> > Oops, I understand that now: 'partial' used to be what 'mixed' is now!
>>> > Our portal usually runs on Java 6u33. For the G1 tests I switched to
>>> 7u7 because I had learned that G1 is far from mature in 6u33.
>>> > But automatic deployments can overwrite the start script and thus
>>> switch back to 6u33.
>>> >
>>> >> Are you sure you are actually using 1.7.0_u7 ?
>>> > I have checked that in the archived start scripts and the result,
>>> unfortunetaley, is: no.
>>> > The 'good case' was actually running on 7u7 (that's why it was good),
>>> but the 'bad case' was unwittingly run on 6u33 again.
>>> > That's the true reason why the results were so much worse and so
>>> incomprehensible.
>>> > Thank you very much for looking at the log and for asking good
>>> questions!
>>> >
>>> > I'll try to repeat the test and post the results on this list.
>>> >
>>> > Regards
>>> > Andreas
>>> > _______________________________________________
>>> > 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
>>>
>>
>>
>
-------------- next part --------------
An HTML attachment was scrubbed...
URL: http://mail.openjdk.java.net/pipermail/hotspot-gc-use/attachments/20121102/d5fadb57/attachment.html 