1.7 G1GC significantly slower than 1.6 Mark and Sweep?

Fri Apr 29 00:23:11 PDT 2011

That's a good idea; I did the runs with G1GC under Java 6 (1.6.0_22), 
and the main thing is that the CPU usage is a lot lower there, although 
I still cannot get results that are as good as with the old CMS gc.

Below some attempts.  I don't know how to activate CMS for Java 7, it 
ignores the option that I'd use for Java 6.

Note that for many of the runs that had a high percentage of long pauses 
or high CPU the program eventually halted (this can be a timing 
threading issue in my code, but it proofs hard to locate if that is the 
case).  For the runs where the long pause percentage is 10% or higher, 
this usually means that every GC resulted in a pause longer than 40ms.  
Collections happen about once or twice per second, so that's a lot of 
too long pauses.

Java7: -ea -Xms256M -Xmx256M
Run 1: CPU: ~90%  Long Pauses: >45%

Java7: -ea -Xms256M -Xmx256M -XX:+UseG1GC
Run 1: CPU: ~90%  Long Pauses: >30%

Java7: -ea -Xms256M -Xmx256M -XX:+UseG1GC -XX:MaxGCPauseMillis=20
Run 1: CPU: >95%  Long Pauses: >25%
* when CPU approaches 100% significantly more long pauses are observed

Java7: -ea -Xms256M -Xmx256M -XX:+UseG1GC -XX:MaxGCPauseMillis=2
Run 1: CPU: >95%  Long Pauses: >30%
* when CPU approaches 100% significantly more long pauses are observed

Java6: -ea -Xms256M -Xmx256M
Run 1: CPU: ~50%  Long Pauses: >30%

Java6: -ea -Xms256M -Xmx256M -XX:UseConcMarkSweepGC -verbose:gc
Run 1: CPU: ~65%  Long Pauses: <1%

Java6: -ea -Xms256M -Xmx256M -XX:+UnlockExperimentalVMOptions 
-XX:+UseG1GC -verbose:gc
Run 1: CPU: ~55%  Long Pauses: ~9%

Java6: -ea -Xms256M -Xmx256M -XX:+UnlockExperimentalVMOptions 
-XX:+UseG1GC -XX:MaxGCPauseMillis=20 -verbose:gc
Run 1: CPU: ~55%  Long Pauses: ~11%
* Pause times were almost always >0.05 seconds, option is ignored?

Java6: -ea -Xms256M -Xmx256M -XX:+UnlockExperimentalVMOptions 
-XX:+UseG1GC -XX:MaxGCPauseMillis=10 -verbose:gc
Run 1: java.lang.OutOfMemoryError: Java heap space (gets stuck in a Full 
GC loop, prints 100+ times [Full GC 214M->210M(256M), 0.0673243 secs])
Run 2: CPU: ~55%  Long Pauses: ~18%
* Pause times were almost always >0.05 seconds, option is ignored?

I'm happy to try any other suggested options/combinations.

--John

Y. Srinivas Ramakrishna wrote:
> John --
>
> How about posting performance/times of each of the 4 combinations
> from the following cartesian product:-
>
>     {JDK7, JDK6} X {CMS, G1}
>
> Perhaps you are conflating JDK changes with GC changes, because
> of changing both axes/dimensions at the same time?
>
> -- ramki
>
> On 4/28/2011 11:10 PM, John Hendrikx wrote:
>> I tried many -XX:MaxGCPauseMillis settings, including not setting it at
>> all, 20, 10, 5, 2.  The results were similar each time -- it didn't
>> really have much of an effect.  In retrospect you might say that the
>> total CPU use is what is causing the problems, not necessarily the
>> length of the pauses -- whether this extra CPU use is caused by the
>> collector or because of some other change in Java 7 I donot know; the
>> program is the same.  Is there perhaps another collector that I could
>> try to see if this lowers CPU use?  Or settings (even non-GC related)
>> that could lower CPU use?
>>
>> Java 6's CMS I didn't need to tune.  After determining that the length
>> of GC pauses was causing problems in the application, I tried turning
>> CMS on and it resolved the problems.
>>
>> What I observe is that even though with Java 7 the pauses seem (are?)
>> very short, the CPU use is a lot higher (from 65% under Java 6 to 95%
>> with 7).  This could be related to other causes (perhaps threading
>> overhead, debug code in Java 7, etc) but I doubt it is in any specific
>> Java code that I wrote as most of the heavy lifting is happening in
>> native methods.  It could for example be that several ByteBuffers being
>> used are being copied under Java 7 while under 6 direct access was 
>> possible.
>>
>> John.
>>
>> Jon Masamitsu wrote:
>>> John,
>>>
>>> You're telling G1 (UseG1GC) to limit pauses to 2ms.
>>> (-XX:MaxGCPauseMillis=2) but seemed to have tuned
>>> CMS (UseConcMarkSweepGC) toward a 20ms goal.
>>> G1 is trying to do very short collections and needs to do many
>>> of them to keep up with the allocation rate.  Did you
>>> mean you are setting MaxGCPauseMillis to 20?
>>>
>>> Jon
>>>
>>> On 4/26/2011 7:59 AM, John Hendrikx wrote:
>>>
>>>> Hi list,
>>>>
>>>> I've been testing Java 1.6 performance vs Java 1.7 performance with a
>>>> timing critical application -- it's essential that garbage collection
>>>> pauses are very short.  What I've found is that Java 1.6 seems to
>>>> perform significantly better than 1.7 (b137) in this respect, although
>>>> with certain settings 1.6 will also fail catastrophically.   I've used
>>>> the following options:
>>>>
>>>> For 1.6.0_22: -Xms256M -Xmx256M -XX:+UseConcMarkSweepGC
>>>> For 1.7.0b137: -Xms256M -Xmx256M  -XX:+UseG1GC -XX:MaxGCPauseMillis=2
>>>>
>>>> The amount of garbage created is roughly 150 MB/sec.  The application
>>>> demands a response time of about 20 ms and uses half a dozen threads
>>>> which deal with buffering and decoding of information.
>>>>
>>>> With the above settings, the 1.6 VM will meet this goal over a 2 
>>>> minute
>>>> period>99% of the time (with an average CPU consumption of 65% per CPU
>>>> core for two cores) -- from verbosegc I gather that the pause times 
>>>> are
>>>> around 0.01-0.02 seconds:
>>>>
>>>> [GC 187752K->187559K(258880K), 0.0148198 secs]
>>>> [GC 192156K(258880K), 0.0008281 secs]
>>>> [GC 144561K->144372K(258880K), 0.0153497 secs]
>>>> [GC 148965K(258880K), 0.0008028 secs]
>>>> [GC 166187K->165969K(258880K), 0.0146546 secs]
>>>> [GC 187935K->187754K(258880K), 0.0150638 secs]
>>>> [GC 192344K(258880K), 0.0008422 secs]
>>>>
>>>> Giving the 1.6 VM more RAM (-Xms1G -Xmx1G) increases these times a 
>>>> bit.
>>>> It can also introduce OutOfMemory conditions and other catastrophic
>>>> failures (one time the GC took 10 seconds after the application had 
>>>> only
>>>> been running 20 seconds).  How stable 1.6 will perform with the 
>>>> initial
>>>> settings remains to be seen; the results with more RAM worry me 
>>>> somewhat.
>>>>
>>>> The 1.7 VM however performs significantly worse.  Here is some of its
>>>> output (over roughtly a one second period):
>>>>
>>>> [GC concurrent-mark-end, 0.0197681 sec]
>>>> [GC remark, 0.0030323 secs]
>>>> [GC concurrent-count-start]
>>>> [GC concurrent-count-end, 0.0060561]
>>>> [GC cleanup 177M->103M(256M), 0.0005319 secs]
>>>> [GC concurrent-cleanup-start]
>>>> [GC concurrent-cleanup-end, 0.0000676]
>>>> [GC pause (partial) 136M->136M(256M), 0.0046206 secs]
>>>> [GC pause (partial) 139M->139M(256M), 0.0039039 secs]
>>>> [GC pause (partial) (initial-mark) 158M->157M(256M), 0.0039424 secs]
>>>> [GC concurrent-mark-start]
>>>> [GC concurrent-mark-end, 0.0152915 sec]
>>>> [GC remark, 0.0033085 secs]
>>>> [GC concurrent-count-start]
>>>> [GC concurrent-count-end, 0.0085232]
>>>> [GC cleanup 163M->129M(256M), 0.0004847 secs]
>>>> [GC concurrent-cleanup-start]
>>>> [GC concurrent-cleanup-end, 0.0000363]
>>>>
>>>>    From the above output one would not expect the performance to be 
>>>> worse,
>>>> however, the application fails to meet its goals 10-20% of the time.
>>>> The amount of garbage created is the same.  CPU time however is 
>>>> hovering
>>>> around 90-95%, which is likely the cause of the poor performance.  The
>>>> GC seems to take a significantly larger amount of time to do its work
>>>> causing these stalls in my test application.
>>>>
>>>> I've experimented with memory sizes and max pause times with the 
>>>> 1.7 VM,
>>>> and although it seemed to be doing better with more RAM, it never 
>>>> comes
>>>> even close to the performance observed with the 1.6 VM.
>>>>
>>>> I'm not sure if there are other useful options I can try to see if 
>>>> I can
>>>> tune the 1.7 VM performance a bit better. I can provide more
>>>> information, although not any (useful) source code at this time due to
>>>> external dependencies (JNA/JNI) of this application.
>>>>
>>>> I'm wondering if I'm missing something as it seems strange to me that
>>>> 1.7 is actually underperforming for me when in general most seem to
>>>> agree that the G1GC is a huge improvement.
>>>>
>>>> --John
>>>>
>>>> _______________________________________________
>>>> 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
>>>
>>>
>>
>> _______________________________________________
>> hotspot-gc-use mailing list
>> hotspot-gc-use at openjdk.java.net
>> http://mail.openjdk.java.net/mailman/listinfo/hotspot-gc-use
>