Parallel GC thread priority

Dmytro Sheyko dmytro_sheyko at hotmail.com
Tue Sep 11 09:52:27 UTC 2012


Hi,

Here is a bit more details:

{Heap before GC invocations=1468 (full 6):
PSYoungGen      total 171904K, used 10352K [0x00000000eaab0000, 0x00000000f6940000, 0x0000000100000000)
  eden space 161536K, 0% used [0x00000000eaab0000,0x00000000eaab0000,0x00000000f4870000)
  from space 10368K, 99% used [0x00000000f5f20000,0x00000000f693c060,0x00000000f6940000)
  to   space 16640K, 0% used [0x00000000f48c0000,0x00000000f48c0000,0x00000000f5900000)
PSOldGen        total 408640K, used 403417K [0x00000000c0000000, 0x00000000d8f10000, 0x00000000eaab0000)
  object space 408640K, 98% used [0x00000000c0000000,0x00000000d89f6478,0x00000000d8f10000)
PSPermGen       total 83968K, used 76315K [0x00000000bae00000, 0x00000000c0000000, 0x00000000c0000000)
  object space 83968K, 90% used [0x00000000bae00000,0x00000000bf886db0,0x00000000c0000000)
2012-03-05T00:03:06.936-0600: 130338.132: [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]
Heap after GC invocations=1468 (full 6):
PSYoungGen      total 171904K, used 0K [0x00000000eaab0000, 0x00000000f6940000, 0x0000000100000000)
  eden space 161536K, 0% used [0x00000000eaab0000,0x00000000eaab0000,0x00000000f4870000)
  from space 10368K, 0% used [0x00000000f5f20000,0x00000000f5f20000,0x00000000f6940000)
  to   space 16640K, 0% used [0x00000000f48c0000,0x00000000f48c0000,0x00000000f5900000)
PSOldGen        total 415872K, used 114637K [0x00000000c0000000, 0x00000000d9620000, 0x00000000eaab0000)
  object space 415872K, 27% used [0x00000000c0000000,0x00000000c6ff3410,0x00000000d9620000)
PSPermGen       total 83968K, used 76315K [0x00000000bae00000, 0x00000000c0000000, 0x00000000c0000000)
  object space 83968K, 90% used [0x00000000bae00000,0x00000000bf886db0,0x00000000c0000000)
}

JVM is x64 Java 7u2.
JVM options are (printed by -XX:+PrintCommandLineFlags):
-XX:InitialHeapSize=536870912 -XX:MaxHeapSize=1073741824 -XX:ParallelGCThreads=4 -XX:+PrintGC -XX:+PrintGCDateStamps -XX:+PrintGCDetails -XX:+PrintGCTimeStamps -XX:+PrintHeapAtGC -XX:+PrintJNIGCStalls -XX:+ReduceSignalUsage -XX:+UseCompressedOops -XX:+UseLargePagesIndividualAllocation -XX:+UseParallelGC

This happened several months ago and many things were changed since that: we added 4G RAM (8G -> 12G), tried other collectors CMS and G1, tried 32 bit, tried other java 7 updates etc. And currently it works pretty well. I doubt I may experiment with our CI server in order to find the real cause of the long GC pause happened before, however please let me know what options are to be set, that would help us to prove that swapping is guilty of such discrepancy between CPU time and wall time if it happens again. I assume that the issue is not specific to PS and it can be observed with CMS and G1 also.

Well, I almost forgot about such issue, but I noticed recently (analyzing jstack output) that Parallel GC threads work with NORM, while G1 and CMS use MAX priority. This seemed to me suspect.
If it is intentional, what is the reason for this?

Recently I wrote simple test (attached) to find out how other cpu-intensive applications impact on GC pauses.
The test does following:
1. figures out Parallel GC threads and their native ids (using jstack)
2. raises their native priority from NORMAL(0) to HIGH(2) (using JNA) (optional)
3. starts java application (Disturber) that simply spins endless loop in several threads (100, configurable) just to consume cpu time.
4. generates garbage to provoke GC.

Used following options:
-Xmx1024m -Xms256m
-server
-showversion
-XX:+PrintGCDetails
-XX:+UseParallelGC
-XX:+UseParallelOldGC
-Ddisturber.java.priority=5
-Dduration.ms=100000
-Ddisturber.threads=100
-Dgc.native.priority=0


Got following results:

1. The test is run without any disturber threads (-Ddisturber.threads=0). Priority of GC threads does not matter. Typical GC log looks like this:
[GC [PSYoungGen: 312502K->0K(349440K)] 898885K->625445K(1048512K), 0.0858486 secs] [Times: user=0.19 sys=0.00, real=0.09 secs] 
[GC [PSYoungGen: 312502K->0K(349440K)] 937947K->664508K(1048512K), 0.0855026 secs] [Times: user=0.19 sys=0.00, real=0.09 secs] 
[Full GC [PSYoungGen: 0K->0K(349440K)] [ParOldGen: 664508K->78570K(699072K)] 664508K->78570K(1048512K) [PSPermGen: 3065K->3065K(16384K)], 0.4356773 secs] [Times: user=0.80 sys=0.00, real=0.44 secs] 
[GC [PSYoungGen: 312502K->0K(349440K)] 391072K->117633K(1048512K), 0.0829569 secs] [Times: user=0.13 sys=0.02, real=0.08 secs] 
[GC [PSYoungGen: 312502K->0K(349440K)] 430135K->156695K(1048512K), 0.0831900 secs] [Times: user=0.19 sys=0.00, real=0.08 secs] 

2. The test is run with 100 disturber threads (-Ddisturber.threads=100). Priority of GC threads remains NORM(0) (-Dgc.native.priority=0). Typical GC log looks like this:
[GC [PSYoungGen: 312502K->0K(349440K)] 664510K->391070K(814976K), 1.9201232 secs] [Times: user=0.13 sys=0.02, real=1.92 secs] 
[GC [PSYoungGen: 312502K->0K(349440K)] 703572K->430133K(814976K), 1.9581938 secs] [Times: user=0.16 sys=0.05, real=1.96 secs] 
[Full GC [PSYoungGen: 0K->0K(349440K)] [ParOldGen: 430133K->78570K(490368K)] 430133K->78570K(839808K) [PSPermGen: 3065K->3065K(16384K)], 8.0233189 secs] [Times: user=0.41 sys=0.00, real=8.02 secs] 
[GC [PSYoungGen: 312502K->0K(349440K)] 391072K->117633K(839808K), 2.1210901 secs] [Times: user=0.13 sys=0.02, real=2.12 secs] 
[GC [PSYoungGen: 312502K->0K(349440K)] 430135K->156695K(839808K), 2.1864928 secs] [Times: user=0.13 sys=0.02, real=2.19 secs] 

3. The test is run with 100 disturber threads (-Ddisturber.threads=100). Priority of GC threads is raisen to HIGH(2) (-Dgc.native.priority=2). Typical GC log looks like this:
[GC [PSYoungGen: 312502K->0K(349440K)] 898885K->625445K(1048512K), 0.0824847 secs] [Times: user=0.16 sys=0.00, real=0.08 secs] 
[GC [PSYoungGen: 312502K->0K(349440K)] 937947K->664508K(1048512K), 0.0823295 secs] [Times: user=0.17 sys=0.00, real=0.08 secs] 
[Full GC [PSYoungGen: 0K->0K(349440K)] [ParOldGen: 664508K->78570K(699072K)] 664508K->78570K(1048512K) [PSPermGen: 3065K->3065K(16384K)], 0.5145061 secs] [Times: user=0.65 sys=0.00, real=0.51 secs] 
[GC [PSYoungGen: 312502K->0K(349440K)] 391072K->117633K(1048512K), 0.0793123 secs] [Times: user=0.16 sys=0.00, real=0.08 secs] 
[GC [PSYoungGen: 312502K->0K(349440K)] 430135K->156695K(1048512K), 0.0809080 secs] [Times: user=0.16 sys=0.00, real=0.08 secs] 

Here I can see that there is a noticeable difference between cpu and wall time of GC pauses in case #2 (when GC threads work with NORM priority and there are cpu intensive applications).

I believe that Parallel GC threads are to be run with HIGH priority (or at least with highest priority of app threads they block), because otherwise there is some sort of priority inversion: GC threads block all application threads even those that run with HIGH priority, however they themself run with NORM priority and can be simply preempted with threads of other app that run with ABOVE_NORM and NORM priority.

Thanks,
Dmytro

Date: Mon, 10 Sep 2012 17:22:51 +0100
Subject: Re: Parallel GC thread priority
From: ysr1729 at gmail.com
To: vitalyd at gmail.com
CC: dmytro_sheyko at hotmail.com; hotspot-gc-dev at openjdk.java.net

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.java.net/pipermail/hotspot-gc-dev/attachments/20120911/1edf9364/attachment.htm>
-------------- next part --------------
An embedded and charset-unspecified text was scrubbed...
Name: Disturber.java
URL: <https://mail.openjdk.java.net/pipermail/hotspot-gc-dev/attachments/20120911/1edf9364/Disturber.java>
-------------- next part --------------
An embedded and charset-unspecified text was scrubbed...
Name: Main.java
URL: <https://mail.openjdk.java.net/pipermail/hotspot-gc-dev/attachments/20120911/1edf9364/Main.java>


More information about the hotspot-gc-dev mailing list