Parallel GC thread priority

[Srinivas Ramakrishna]

I agree that eliminating paging as a suspect is a good idea. Although the
stats that Dmytro provided below seems to show plenty of free RAM, perhaps
that info was collected at a different time than when the long pause was
observed?

Like Vitaly, I am suspicious of paging in such extreme cases.

What's the version of JVM you are running? (In such cases running with
-XX:+PrintGCTimeStamps -XX:+PrintGCDateStamps would have been great as it
just might have provided a couple more clues -- or not.)
(There were some older versions of the JVM where there were issues with
thread suspension that would cause long pauses, but i believe the GC log
symptom of that was somewhat different.)

By the way, since this is a 4 core system, you should be running
-XX:+UseParallelOldGC.

Note, for that reason, that "parallel gc thread" priority is moot for this
case, it's really "(serial) GC thread", since there's a single GC thread
running your full collection below. (Although your minor collections are
indeed run multi-threaded.)

-- ramki

On Fri, Sep 7, 2012 at 5:53 PM, Vitaly Davidovich <vitalyd at gmail.com> wrote:

> I see you're on windows, but on Linux I'm almost certain that time spent
> waiting for i/o does not count in sys time (it's purely CPU time).  I
> suspect, though, that windows does similar accounting but I'm not sure.
>
> Sent from my phone
> On Sep 7, 2012 12:31 PM, "Dmytro Sheyko" <dmytro_sheyko at hotmail.com>
> wrote:
>
>>  Hi,
>>
>> I can provide following info only:
>> ===
>> System:
>>  Microsoft Windows Server 2003 R2
>>  Standard x64 Edition
>>  Service Pack 2
>> Computer:
>>  Intel(R) Xeon(R) CPU E5-2640
>>  2.50 GHz, 12.0 GB of RAM
>> ===
>> JConsole output:
>>
>> Operating System:       Windows 2003 5.2
>> Architecture:           amd64
>> Number of processors:   4
>>
>> Total physical memory:  12,582,100 kbytes
>> Free physical memory:    6,184,012 kbytes
>> Total swap space:       14,137,188 kbytes
>> Free swap space:        11,189,520 kbytes
>> ===
>> But at time that this long GC pause happened it was 8 GB of RAM. And I
>> don't know how much memory was used at that time.
>>
>> Please note that it's continuous integration server. Some build tasks are
>> executed on the same machine. The pause happened on web server, which
>> serves UI.
>>
>> BTW, isn't swapping counted as sys/kernel time?
>>
>> Thanks,
>> Dmytro
>>
>>
>> ------------------------------
>> Date: Fri, 7 Sep 2012 11:45:34 -0400
>> Subject: Re: Parallel GC thread priority
>> From: vitalyd at gmail.com
>> To: azeem.jiva at oracle.com
>> CC: dmytro_sheyko at hotmail.com; hotspot-gc-dev at openjdk.java.net
>>
>> Whether it helps or not would depend on what priority the other threads
>> are running at.  If the server had several jvms running at the same time
>> and they all start a par new collection at about the same time, then yeah
>> it won't help if priority is boosted - at that point, the machine is simply
>> oversubscribed.
>> In Dmytro's case, the wall time is so out of whack with CPU time that I
>> wonder if it wasn't swapping that mostly contributed to this.  For such a
>> relatively small heap, I can't imagine how much other stuff would have to
>> run to inflate the time so much.
>> Dmytro, what hardware spec was this on, out of curiosity?
>> Sent from my phone
>> On Sep 7, 2012 11:39 AM, "Azeem Jiva" <azeem.jiva at oracle.com> wrote:
>>
>>  I had not thought about other processes, which is a possibility.
>> Although raising the priority of the GC threads won't help which I believe
>> what Dmytro was suggestion.
>>
>>
>> On 09/07/2012 10:35 AM, Vitaly Davidovich wrote:
>>
>> You can have other threads from different processes in the system
>> competing though.
>> However, such a large wall time vs CPU time can also be caused by heavy
>> swapping on a slow disk.  The heap there doesn't look all that big though
>> ...
>> Sent from my phone
>> On Sep 7, 2012 11:21 AM, "Azeem Jiva" <azeem.jiva at oracle.com> wrote:
>>
>>  The Parallel collector is a stop-the-world collector.  The Java threads
>> are suspended until the GC finishes.  I think your survivor spaces maybe
>> mis-configured, and that's why you're seeing such large GC times.
>>
>>
>> On 09/07/2012 10:17 AM, Dmytro Sheyko wrote:
>>
>>  Hi,
>>
>> I can see that Parallel GC works on threads with NormPriority, while CMS
>> and G1 threads run with NearMaxPriority. This probably not an issue if java
>> application works alone, but some time ago I observed GC log like this (it
>> was Jenkins CI on Windows):
>>
>> [Full GC [PSYoungGen: 10352K->0K(171904K)] [PSOldGen:
>> 403417K->114637K(415872K)] 413769K->114637K(587776K) [PSPermGen:
>> 76315K->76315K(83968K)], 30.2595731 secs] [Times: user=0.77 sys=0.41,
>> real=30.26 secs]
>>
>> Despite cpu time for GC was just 1.18 sec (= 0.77 + 0.41), the real time
>> was 30.26 sec! It seems to me that the system was busy that time and GC
>> threads was starving.
>>
>> If we could raise priority of Parallel GC threads, other application
>> would have less impact on GC duration.
>>
>> What do you think?
>>
>> Thanks,
>> Dmytro
>>
>>
>> --
>> Azeem Jiva
>> @javawithjiva
>>
>>
>> --
>> Azeem Jiva
>> @javawithjiva
>>
>>
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <https://mail.openjdk.org/pipermail/hotspot-gc-dev/attachments/20120910/c8cf9031/attachment.htm>