You may want to set -XX:+PrintTenuringDistribution or attach with VisualGC or VisualVM to check whether the survivor space should be increased to avoid premature tenuring of objects into old. Similarly, perhaps -Xmn should be increased depending of the lifespans of your objects. Note that -XX:+ParallelOldGC uses implicitly -XX:+UseParallelGC (the throughput collector) whereas -XX:+UseConcMarkSweepGC uses -XX:+UseParNewGC (the low-pause collector) so the characteristics of the collections will most likely change a bit. I don't know whether -XX:+UseParallelGC automagically also turns on -XX:+UseAdaptiveSizing or not. Ramki? In any case, since we can't see the cause of the FullGC, perhaps -XX:+HandlePromotionFailure could help if this is due to a Young Guarantee GC rather than an OldFull or OldTooFull GC. Another hypothesis could be that you are running out of Perm space. Perhaps you need to set -XX:PermSize=64M which would be equal to -XX:MaxPermSize default size of 64M as increases of Perm also cause FullGC. Lastly, is there any possibility of using multiple smaller JVMs to avoid the super-long pauses in this 12GB one?<br>
Cheers,<br>Fino<br><br><div class="gmail_quote">On Tue, Mar 18, 2008 at 8:37 PM, Y Srinivas Ramakrishna <<a href="mailto:Y.S.Ramakrishna@sun.com">Y.S.Ramakrishna@sun.com</a>> wrote:<br><blockquote class="gmail_quote" style="border-left: 1px solid rgb(204, 204, 204); margin: 0pt 0pt 0pt 0.8ex; padding-left: 1ex;">
<br>
Hi Karl --<br>
<br>
When the long response times are seen, the free memory jumps from about ~300 MB<br>
free to about ~4GB free. So it would seem as though the 60 s pauses are likely the<br>
serial compaction of the 12 GB heap. I would suggest either using -XX:+UseParalleOldGC<br>
(to compact the heap in parallel on the 4 cpus), or if that does not help enough (recall that<br>
1.5.0_XX was the first version of parallel compaction and many performance enhancements<br>
were made to it subsequently in 6uXX which are not in 1.5.0_XX), then try -XX:+UseConcMarkSweepGC.<br>
<br>
Tuning docs etc can be found starting from:<br>
<br>
    <a href="http://java.sun.com/javase/technologies/hotspot/index.jsp" target="_blank">http://java.sun.com/javase/technologies/hotspot/index.jsp</a><br>
    <a href="http://java.sun.com/javase/technologies/hotspot/gc/index.jsp" target="_blank">http://java.sun.com/javase/technologies/hotspot/gc/index.jsp</a><br>
<br>
GC logs using -XX:+PrintGCDetails will of course clarify matters more. There may be other<br>
flags with each of the parallel old and cms collectors that would provide more statistics<br>
as to where the time is going.<br>
<br>
HTHS.<br>
-- ramki<br>
<div><div></div><div class="Wj3C7c"><br>
<br>
----- Original Message -----<br>
From: Karl Rosenbaum <<a href="mailto:kalle@rosenbaum.se">kalle@rosenbaum.se</a>><br>
Date: Tuesday, March 18, 2008 7:59 am<br>
Subject: Long pauses with parallel collector<br>
To: <a href="mailto:hotspot-gc-use@openjdk.java.net">hotspot-gc-use@openjdk.java.net</a><br>
Cc: <a href="mailto:mikael.lonneberg@telelogic.com">mikael.lonneberg@telelogic.com</a>, Mattias Fredsberg <<a href="mailto:mattias.fredsberg@focalpoint.se">mattias.fredsberg@focalpoint.se</a>><br>
<br>
<br>
> Hi<br>
><br>
> We're experiencing long pauses (>60 seconds) using the parallel<br>
> collector and the serial compacting old generation collector (the<br>
> default choice on a server-class machine, right?). Unfortunately we<br>
> have<br>
> no logs from the gc, since this is a customer's installation and we<br>
> can't play around with that. But I do have memory statistics along<br>
> with<br>
> response time statistics. Before the problems started we didn't really<br>
><br>
> notice the collections but recently the collections took more than 60<br>
><br>
> seconds. This is measured using wget on a "ping"-servlet that returns<br>
><br>
> some memory statistics. The RESPTIME is measured by timing the<br>
> wget-command. FREE MEM, MEM TOTAL and MEM ALLOCATED are the results of<br>
><br>
>                  long freeMem = Runtime.getRuntime().freeMemory();<br>
>                  long totalMem = Runtime.getRuntime().totalMemory();<br>
>                  long allocMem = Runtime.getRuntime().maxMemory();<br>
><br>
><br>
> This is an example of the statistics before the problems started:<br>
><br>
> TIME          FREE MEM        MEM TOTAL       MEM ALLOCATED   RESPTIME<br>
> 10:59:49      1499233752      12724273152     12724273152     0.20<br>
> 10:59:59      1431576712      12724273152     12724273152     0.16<br>
> 11:00:09      1392930432      12724273152     12724273152     0.14<br>
> 11:00:19      1385974568      12724273152     12724273152     0.13<br>
> 11:00:30      1365510896      12724273152     12724273152     0.13<br>
> 11:00:40      1248830048      12724273152     12724273152     0.19<br>
> 11:00:50      1164298568      12724273152     12724273152     0.13<br>
> 11:01:00      1122874896      12724273152     12724273152     0.15<br>
> 11:01:10      1085027216      12724273152     12724273152     0.13<br>
> 11:01:20      952254960       12724273152     12724273152     0.14<br>
> 11:01:31      385638352       12724273152     12724273152     0.30<br>
> 11:01:41      3905940544      12717326336     12717326336     0.13<br>
> 11:01:51      3286915952      12717326336     12717326336     0.34<br>
> 11:02:01      1862466680      12717326336     12717326336     0.17<br>
> 11:02:12      1214561176      12717326336     12717326336     0.13<br>
> 11:02:22      937846336       12717326336     12717326336     0.13<br>
> 11:02:32      830626208       12717326336     12717326336     0.13<br>
> 11:02:42      591847776       12717326336     12717326336     0.13<br>
> 11:02:52      486858808       12717326336     12717326336     0.15<br>
> 11:03:02      405118840       12717326336     12717326336     0.12<br>
> 11:03:12      379997776       12717326336     12717326336     0.17<br>
> 11:03:23      4231164944      12723027968     12723027968     0.13<br>
> 11:03:33      2869501088      12723027968     12723027968     0.14<br>
> 11:03:43      2848014968      12723027968     12723027968     0.15<br>
> 11:03:53      2789025152      12723027968     12723027968     0.13<br>
> 11:04:03      2141846392      12723027968     12723027968     0.14<br>
> 11:04:13      1936386592      12723027968     12723027968     0.13<br>
> 11:04:24      1922345160      12723027968     12723027968     0.13<br>
> 11:04:34      1907951992      12723027968     12723027968     0.14<br>
> 11:04:44      1884581280      12723027968     12723027968     0.15<br>
> 11:04:54      1842599720      12723027968     12723027968     0.14<br>
> 11:05:04      1833357144      12723027968     12723027968     0.14<br>
> 11:05:14      819218528       12723027968     12723027968     0.15<br>
> 11:05:25      766194152       12723027968     12723027968     0.14<br>
> 11:05:35      738061968       12723027968     12723027968     0.14<br>
> 11:05:45      716541120       12723027968     12723027968     0.13<br>
> 11:05:55      690620328       12723027968     12723027968     0.13<br>
> 11:06:05      601896808       12723027968     12723027968     0.13<br>
> 11:06:15      3986587288      12721192960     12721192960     0.19<br>
> 11:06:26      3981820120      12721192960     12721192960     0.19<br>
> 11:06:36      3908686896      12721192960     12721192960     0.13<br>
> 11:06:46      3896673928      12721192960     12721192960     0.13<br>
><br>
><br>
> This is an example of the statistics after the problems started:<br>
><br>
> TIME          FREE MEM        MEM TOTAL       MEM ALLOCATED   RESPTIME<br>
> 15:26:13      132104472       12878741504     12878741504     0.11<br>
> 15:26:23      89372112        12878741504     12878741504     0.21<br>
> 15:26:33      61732520        12878741504     12878741504     0.12<br>
> 15:26:43      15401280        12878741504     12878741504     12.14<br>
> 15:27:05      4074793624      12878741504     12878741504     64.57<br>
> 15:28:20      3378764376      12878741504     12878741504     0.12<br>
> 15:28:30      2858626704      12878741504     12878741504     0.11<br>
> 15:28:40      491173584       12878741504     12878741504     0.11<br>
> 15:28:50      414802056       12878741504     12878741504     0.92<br>
> 15:29:01      298133928       12878741504     12878741504     0.20<br>
> 15:29:12      4164253720      12878741504     12878741504     64.36<br>
> 15:30:26      3662076152      12878741504     12878741504     0.15<br>
> 15:30:36      1823630328      12878741504     12878741504     0.11<br>
> 15:30:46      1338510584      12878741504     12878741504     0.12<br>
> 15:30:56      505714912       12878741504     12878741504     0.11<br>
> 15:31:07      320903520       12878741504     12878741504     0.11<br>
> 15:31:17      4179464600      12878741504     12878741504     71.62<br>
> 15:32:38      3001104680      12878741504     12878741504     0.47<br>
> 15:32:49      2593399336      12878741504     12878741504     0.13<br>
> 15:32:59      2478360368      12878741504     12878741504     0.11<br>
> 15:33:09      2391502968      12878741504     12878741504     0.11<br>
> 15:33:19      785466304       12878741504     12878741504     0.13<br>
> 15:33:29      4004574384      12878741504     12878741504     62.87<br>
> 15:34:42      2643636392      12878741504     12878741504     0.11<br>
> 15:34:52      2387674096      12878741504     12878741504     0.15<br>
> 15:35:03      2226430872      12878741504     12878741504     0.11<br>
> 15:35:13      1016694456      12878741504     12878741504     0.11<br>
> 15:35:23      728910648       12878741504     12878741504     0.11<br>
> 15:35:33      238095528       12878741504     12878741504     7.11<br>
> 15:35:50      215109328       12878741504     12878741504     0.11<br>
> 15:36:00      4025070120      12878741504     12878741504     69.14<br>
> 15:37:19      2294767768      12878741504     12878741504     0.12<br>
> 15:37:30      1897269848      12878741504     12878741504     0.11<br>
> 15:37:40      1832375800      12878741504     12878741504     0.30<br>
> 15:37:50      1741032976      12878741504     12878741504     0.11<br>
> 15:38:00      1641480032      12878741504     12878741504     0.18<br>
> 15:38:10      774869968       12878741504     12878741504     7.20<br>
> 15:38:28      634489992       12878741504     12878741504     0.10<br>
> 15:38:38      274370880       12878741504     12878741504     3.11<br>
> 15:38:51      68896328        12878741504     12878741504     0.11<br>
> 15:39:01      31211120        12878741504     12878741504     0.15<br>
> 15:39:11      3997617032      12878741504     12878741504     60.77<br>
><br>
> As you can see, every collection results in a >60 seconds pause time.<br>
><br>
> The server have been restarted once between the two log snippets and<br>
> they are from different dates. The problem lasted indefinitely and all<br>
><br>
> collections seem to take this long.<br>
><br>
> We have now applied the CMS collector to "kill" these symptoms, but we<br>
><br>
> still need to understand what was going on here.<br>
><br>
> Do you have any suggestions on what the cause of this might be?<br>
><br>
> The server is a Solaris 10 sparc machine with 16GB memory and 4 cpus.<br>
><br>
> The java version is 1.5.0_11<br>
><br>
> These are the java parameters:<br>
> root@fp # pargs 10502<br>
><br>
> 10502:  /usr/jdk/instances/jdk1.5.0/bin/sparcv9/java -Xmx12288m<br>
> -Dmx=12288 -Djava.awt.h<br>
> argv[0]: /usr/jdk/instances/jdk1.5.0/bin/sparcv9/java<br>
> argv[1]: -Xmx12288m<br>
> argv[2]: -Dmx=12288<br>
> argv[3]: -Djava.awt.headless=true<br>
> argv[4]: -Dfile.encoding=UTF-8<br>
> argv[5]: -Djava.library.path=/opt/FOCAfp/lib<br>
> argv[6]: -Djava.util.logging.manager=org.apache.juli.ClassLoaderLogManager<br>
> argv[7]: -Djava.endorsed.dirs=/opt/FOCAtomcat/common/endorsed<br>
> argv[8]: -classpath<br>
> argv[9]:<br>
> :/opt/FOCAtomcat/bin/bootstrap.jar:/opt/FOCAtomcat/bin/commons-logging-api.jar<br>
> argv[10]: -Dcatalina.base=/opt/FOCAtomcat<br>
> argv[11]: -Dcatalina.home=/opt/FOCAtomcat<br>
> argv[12]: -Djava.io.tmpdir=/opt/FOCAtomcat/temp<br>
> argv[13]: org.apache.catalina.startup.Bootstrap<br>
> argv[14]: start<br>
><br>
><br>
> Best regards,<br>
> Karl Rosenbaum<br>
> _______________________________________________<br>
> hotspot-gc-use mailing list<br>
> <a href="mailto:hotspot-gc-use@openjdk.java.net">hotspot-gc-use@openjdk.java.net</a><br>
> <a href="http://mail.openjdk.java.net/mailman/listinfo/hotspot-gc-use" target="_blank">http://mail.openjdk.java.net/mailman/listinfo/hotspot-gc-use</a><br>
_______________________________________________<br>
hotspot-gc-use mailing list<br>
<a href="mailto:hotspot-gc-use@openjdk.java.net">hotspot-gc-use@openjdk.java.net</a><br>
<a href="http://mail.openjdk.java.net/mailman/listinfo/hotspot-gc-use" target="_blank">http://mail.openjdk.java.net/mailman/listinfo/hotspot-gc-use</a><br>
</div></div></blockquote></div><br><br clear="all"><br>-- <br>Michael Finocchiaro<br><a href="mailto:michael.finocchiaro@gmail.com">michael.finocchiaro@gmail.com</a><br>Mobile Telephone: +33 6 67 90 64 39<br>MSN: <a href="mailto:le_fino@hotmail.com">le_fino@hotmail.com</a>