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