<!DOCTYPE HTML PUBLIC "-//W3C//DTD HTML 4.01 Transitional//EN">
<html>
<head>
<meta content="text/html; charset=ISO-8859-15"
http-equiv="Content-Type">
</head>
<body bgcolor="#ffffff" text="#000000">
Hi David -- you have a 48 core machine but you have handicapped yr
JVM by forcing -XX:-CMSParallelRemarkEnabled,<br>
which forces single--threaded remarks on such a huge heap. Please
remove that flag so all 48 cores can be<br>
used for the remark pause (and it should disappear from your
pause-time radar entirely i think). If "ref proc"<br>
turns out to be still a problem, you can then enable
+ParallelRefProcEnabled to parallelize that sub-phase as well.<br>
<br>
As to the 20 s pause in the middle of nowhere, I am clueless, but
switch on -XX:+PrintSfaepointStatistics<br>
to see what that long pause corresponds to. Perhaps some kind of
bulk bias revocation perhaps, I am<br>
not sure...<br>
<br>
-- ramki<br>
<br>
<br>
On 8/29/2011 2:25 AM, David Tavoularis wrote:
<blockquote cite="mid:op.v0yxs0vga5r2ku@nb07-spt1.mycom-int.fr"
type="cite">
<meta http-equiv="Content-Type" content="text/html;
charset=ISO-8859-15">
<style type="text/css">
<!--
body
{font-family:'Calibri';
font-size:18px}
-->
</style>
<div>Hi,<br>
<br>
I am trying to understand the cause of "stop-the-world" pauses
in my application using CMS GC and a large heap (48GB).<br>
The production server SF6900 <font face="'Consolas',monospace"><small>(24
x dual-core UltraSparc-IV 1.35GHz, 48 working threads, 140GB
RAM)</small></font> is running on Solaris 9 and Java6u25.<br>
<br>
I know that there are several possible causes :<br>
1) OldGen fragmentation : to avoid it, I implemented an
automatic FullGC in crontab at 2:30am<br>
<font face="'Consolas',monospace"><small>30 2 * * *
/usr/jdk/instances/jdk1.6.0/bin/jmap -d64 -histo:live
`/usr/bin/pgrep -f "XXXXXXX"` 2>&1 >/dev/null</small></font><br>
<br>
2) Weak refs processing : a workaround (not tried yet) is to use
-XX:+ParallelRefProcEnabled, as described in the following
articles :<br>
<a moz-do-not-send="true"
href="http://blogs.oracle.com/jonthecollector/entry/top_10_gc_reasons">http://blogs.oracle.com/jonthecollector/entry/top_10_gc_reasons</a><br>
<a moz-do-not-send="true"
href="http://stackoverflow.com/questions/4101540/how-can-i-lower-the-weak-ref-processing-time-during-gc">http://stackoverflow.com/questions/4101540/how-can-i-lower-the-weak-ref-processing-time-during-gc</a><br>
I have found out that it could be triggered by the daily
unreferencing of a big object containing millions of small
objects (using weak references).<br>
<br>
<br>
The application has been running for almost a week and I can see
some "stop-the-world" pauses longer than 10 seconds :<br>
<font face="'Consolas',monospace"><small><strong>$ egrep "Total
time for which application threads were stopped:
[0-9][0-9]\." gc_201108232207.log</strong></small><small><br>
</small><small>Total time for which application threads were
stopped: </small></font><font face="'Consolas',monospace"><small><strong><font
color="#ff0000">10</font></strong></small></font><font
face="'Consolas',monospace"><small>.8630158 seconds
<strong><font color="#0000a0"><- due to weak refs</font></strong></small><small><br>
</small><small>Total time for which application threads were
stopped: <strong><font color="#ff0000">18</font></strong>.5259611
seconds</small><small><br>
</small><small>Total time for which application threads were
stopped: <strong><font color="#ff0000">10</font></strong>.0777809
seconds
<strong><font color="#0000a0"><- due to weak refs</font></strong></small><small><br>
</small><small>Total time for which application threads were
stopped: </small></font><font face="'Consolas',monospace"><strong><font
color="#ff0000">61</font></strong></font><font
face="'Consolas',monospace"><small>.5576519 seconds</small><small><br>
</small><small>Total time for which application threads were
stopped: <strong><font color="#ff0000">19</font></strong>.0205127
seconds</small><small><br>
</small><small>Total time for which application threads were
stopped: <font color="#ff0000">
<strong>20</strong></font>.6893643 seconds</small><small><br>
</small><small>Total time for which application threads were
stopped: <font color="#ff0000">
<strong>16</strong></font>.0048075 seconds</small><small><br>
</small><small>Total time for which application threads were
stopped: <font color="#ff0000">
<strong>12</strong></font>.3665083 seconds <strong><font
color="#0000a0"><- due to weak refs</font></strong></small><small><br>
</small><small>Total time for which application threads were
stopped: <strong><font color="#ff0000">11</font></strong>.5213443
seconds
<strong><font color="#0000a0"><- due to weak refs</font></strong></small><small><br>
</small><small>Total time for which application threads were
stopped: <strong><font color="#ff0000">37</font></strong>.1018520
seconds
<strong><font color="#0000a0"><- due to weak refs</font></strong></small><small><br>
</small><small>Total time for which application threads were
stopped: <strong><font color="#ff0000">16</font></strong>.3988783
seconds
<strong><font color="#0000a0"><- due to weak refs</font></strong></small><small><br>
</small><small>Total time for which application threads were
stopped: <strong><font color="#ff0000">12</font></strong>.4057546
seconds</small></font><br>
</div>
<div><br>
</div>
<div>6 of them have unknown explanation for me.</div>
<div><br>
For your information, here are the 6 "weak refs" log messages :<br>
$ egrep "weak refs processing, [1-9][0-9]?" gc_201108232207.log
| more<font face="'Consolas',monospace"><br>
<small>2011-08-24T10:13:49.641+0100: 43564.409: [GC[YG
occupancy: 342791 K (943744 K)]43564.410: [Rescan
(non-parallel) 43564.410: [grey object rescan, 0.7358794
secs]43565.146: [root rescan, 1.9033345 secs], 2.6398211
secs]43567.049: [weak refs processing, 8.2148555 secs] [1
CMS-remark: 26914465K(49283072K)] 27257257K(50226816K),
10.8566498 secs]
<strong><font color="#ff0000">[Times: user=10.85 sys=0.00,
real=10.86 secs]</font></strong></small><small><br>
</small><small>2011-08-25T12:33:22.658+0100: 138336.194:
[GC[YG occupancy: 179985 K (943744 K)]138336.195: [Rescan
(non-parallel) 138336.195: [grey object rescan, 0.5969886
secs]138336.792: [root rescan, 0.5114118 secs], 1.1089811
secs]138337.304: [weak refs processing, 8.8414246 secs] [1
CMS-remark: 20122279K(49283072K)] 20302264K(5226816K),
9.9514563 secs]
<font color="#ff0000"><strong>[Times: user=9.94 sys=0.01,
real=9.95 secs]</strong></font></small><small><br>
</small><small>2011-08-26T07:22:55.233+0100: 206107.887:
[GC[YG occupancy: 177014 K (943744 K)]206107.888: [Rescan
(non-parallel) 206107.888: [grey object rescan, 0.4472730
secs]206108.335: [root rescan, 1.5575365 secs], 2.0053337
secs]206109.893: [weak refs processing, 10.3436973 secs] [1
CMS-remark: 19861286K(49283072K)] 20038301K(50226816K),
12.3572481 secs]
<strong><font color="#ff0000">[Times: user=12.22 sys=0.00,
real=12.36 secs]</font></strong></small><small><br>
</small><small>2011-08-26T07:51:55.531+0100: 207848.163:
[GC[YG occupancy: 423184 K (943744 K)]207848.163: [Rescan
(non-parallel) 207848.163: [grey object rescan, 0.4466552
secs]207848.610: [root rescan, 3.4207362 secs], 3.8680060
secs]207852.031: [weak refs processing, 7.6403893 secs] [1
CMS-remark: 19714349K(49283072K)] 20137533K(50226816K),
11.5130922 secs]
<strong><font color="#ff0000">[Times: user=11.51 sys=0.00,
real=11.51 secs]</font></strong></small><small><br>
</small><small>2011-08-27T15:18:48.928+0100: 321060.091:
[GC[YG occupancy: 711567 K (943744 K)]321060.092: [Rescan
(non-parallel) 321060.092: [grey object rescan, 0.4628955
secs]321060.555: [root rescan, 3.2087381 secs], 3.6721710
secs]321063.764: [weak refs processing, 33.3995481 secs] [1
CMS-remark: 19918243K(49283072K)] 20629810K(50226816K),
37.0910804 secs]
<strong><font color="#ff0000">[Times: user=37.04 sys=0.00,
real=37.09 secs]</font></strong></small><small><br>
</small><small>2011-08-28T11:17:12.144+0100: 392962.378:
[GC[YG occupancy: 811576 K (943744 K)]392962.378: [Rescan
(non-parallel) 392962.378: [grey object rescan, 0.4140054
secs]392962.793: [root rescan, 4.4323136 secs], 4.8469694
secs]392967.225: [weak refs processing, 11.5384812 secs] [1
CMS-remark: 19819290K(49283072K)] 20630867K(50226816K),
16.3885374 secs]
<strong><font color="#ff0000">[Times: user=16.35 sys=0.01,
real=16.39 secs]</font></strong></small></font><br>
<br>
<br>
</div>
<div><br>
</div>
<div><br>
</div>
<div><br>
</div>
<div><br>
</div>
<div><strong>1. Here is the first pattern : a <u>61-second pause</u>,
but I don't see any suspicious message in GC logs:</strong><br>
<font face="'Consolas',monospace"><small>2011-08-24T10:24:25.748+0100:
44200.509: [GC 44200.511: [ParNew</small><small><br>
</small><small>Desired survivor size 53673984 bytes, new
threshold 1 (max 4)</small><small><br>
</small><small>- age 1: 101879520 bytes, 101879520 total</small><small><br>
</small><small>: 933589K->104832K(943744K), 0.3947382 secs]
21369469K->20703994K(50226816K), 0.3966779 secs] [Times:
user=6.43 sys=0.04, real=0.40 secs]</small><small><br>
</small><small>Heap after GC invocations=1187 (full 12):</small><small><br>
</small><small>par new generation total 943744K, used 104832K
[0xfffffff353c00000, 0xfffffff393c00000, 0xfffffff393c00000)</small><small><br>
</small><small>eden space 838912K, 0% used
[0xfffffff353c00000, 0xfffffff353c00000, 0xfffffff386f40000)</small><small><br>
</small><small>from space 104832K, 100% used
[0xfffffff386f40000, 0xfffffff38d5a0000, 0xfffffff38d5a0000)</small><small><br>
</small><small>to space 104832K, 0% used [0xfffffff38d5a0000,
0xfffffff38d5a0000, 0xfffffff393c00000)</small><small><br>
</small><small>concurrent mark-sweep generation total
49283072K, used 20599162K [0xfffffff393c00000,
0xffffffff53c00000, 0xffffffff53c00000)</small><small><br>
</small><small>concurrent-mark-sweep perm gen total 524288K,
used 42905K [0xffffffff53c00000, 0xffffffff73c00000,
0xffffffff73c00000)</small><small><br>
</small><small>}</small><small><br>
</small><small>Total time for which application threads were
stopped: 0.4110458 seconds</small><small><br>
</small><small>Application time: 39.5906692 seconds</small><small><br>
</small><small>{Heap before GC invocations=1187 (full 12):</small><small><br>
</small><small>par new generation total 943744K, used 943744K
[0xfffffff353c00000, 0xfffffff393c00000, 0xfffffff393c00000)</small><small><br>
</small><small>eden space 838912K, 100% used
[0xfffffff353c00000, 0xfffffff386f40000, 0xfffffff386f40000)</small><small><br>
</small><small>from space 104832K, 100% used
[0xfffffff386f40000, 0xfffffff38d5a0000, 0xfffffff38d5a0000)</small><small><br>
</small><small>to space 104832K, 0% used [0xfffffff38d5a0000,
0xfffffff38d5a0000, 0xfffffff393c00000)</small><small><br>
</small><small>concurrent mark-sweep generation total
49283072K, used 20599162K [0xfffffff393c00000,
0xffffffff53c00000, 0xffffffff53c00000)</small><small><br>
</small><small>concurrent-mark-sweep perm gen total 524288K,
used 42905K [0xffffffff53c00000, 0xffffffff73c00000,
0xffffffff73c00000)</small><small><br>
</small><small>2011-08-24T10:25:07.776+0100: 44242.537: [GC
44301.853: [ParNew</small><small><br>
</small><small>Desired survivor size 53673984 bytes, new
threshold 1 (max 4)</small><small><br>
</small><small>- age 1: 99505080 bytes, 99505080 total</small><small><br>
</small><small>: 943744K->104832K(943744K), 0.2010508 secs]
21542906K->20852742K(50226816K), 0.2022636 secs]
<font color="#ff0000"><strong>[Times: user=5.67 sys=0.02,
real=59.52 secs]</strong></font></small><small><br>
</small><small>Heap after GC invocations=1188 (full 12):</small><small><br>
</small><small>par new generation total 943744K, used 104832K
[0xfffffff353c00000, 0xfffffff393c00000, 0xfffffff393c00000)</small><small><br>
</small><small>eden space 838912K, 0% used
[0xfffffff353c00000, 0xfffffff353c00000, 0xfffffff386f40000)</small><small><br>
</small><small>from space 104832K, 100% used
[0xfffffff38d5a0000, 0xfffffff393c00000, 0xfffffff393c00000)</small><small><br>
</small><small>to space 104832K, 0% used [0xfffffff386f40000,
0xfffffff386f40000, 0xfffffff38d5a0000)</small><small><br>
</small><small>concurrent mark-sweep generation total
49283072K, used 20747910K [0xfffffff393c00000,
0xffffffff53c00000, 0xffffffff53c00000)</small><small><br>
</small><small>concurrent-mark-sweep perm gen total 524288K,
used 42905K [0xffffffff53c00000, 0xffffffff73c00000,
0xffffffff73c00000)</small><small><br>
</small><small>}</small><small><br>
</small><small><strong><font color="#ff0000">Total time for
which application threads were stopped: 61.5576519
seconds</font></strong></small><small><br>
</small><small>Application time: 0.0245838 seconds</small><small><br>
</small><small>Total time for which application threads were
stopped: 9.8331189 seconds</small><small><br>
</small><small>Application time: 0.0012626 seconds</small><small><br>
</small><small>Total time for which application threads were
stopped: 0.0090404 seconds</small><small><br>
</small><small>Application time: 0.0008943 seconds</small><small><br>
</small><small>Total time for which application threads were
stopped: 0.0020415 seconds</small><small><br>
</small><small>Application time: 0.0008181 seconds</small><small><br>
</small><small>Total time for which application threads were
stopped: 0.2338605 seconds</small><small><br>
</small><small>Application time: 0.0018822 seconds</small></font><br>
<br>
The only suspicious thing is <font face="'Consolas',monospace"><small>"[Times:
user=5.67 sys=0.02, real=59.52 secs]"</small></font>, which
means that the "real" duration is a lot higher than "user" CPU
time.<br>
Because "sys" duration is low, it also means that the server is
not swapping.<br>
</div>
<div>What could explain this 61 seconds pause ? </div>
<div><br>
</div>
<div><br>
</div>
<div><br>
</div>
<div><strong>2. Here is the second pattern : a 20-second pause, in
the middle of nowhere in GC logs :</strong></div>
<div><font face="'Consolas',monospace"><small>{Heap before GC
invocations=11132 (full 166):</small><small><br>
</small><small>par new generation total 943744K, used 882686K
[0xfffffff353c00000, 0xfffffff393c00000, 0xfffffff393c00000)</small><small><br>
</small><small>eden space 838912K, 100% used
[0xfffffff353c00000, 0xfffffff386f40000, 0xfffffff386f40000)</small><small><br>
</small><small>from space 104832K, 41% used
[0xfffffff386f40000, 0xfffffff3899ffa48, 0xfffffff38d5a0000)</small><small><br>
</small><small>to space 104832K, 0% used [0xfffffff38d5a0000,
0xfffffff38d5a0000, 0xfffffff393c00000)</small><small><br>
</small><small>concurrent mark-sweep generation total
49283072K, used 19148140K [0xfffffff393c00000,
0xffffffff53c00000, 0xffffffff53c00000)</small><small><br>
</small><small>concurrent-mark-sweep perm gen total 524288K,
used 44308K [0xffffffff53c00000, 0xffffffff73c00000,
0xffffffff73c00000)</small><small><br>
</small><small>2011-08-25T20:07:07.235+0100: 165560.417: [GC
165560.417: [ParNew</small><small><br>
</small><small>Desired survivor size 53673984 bytes, new
threshold 4 (max 4)</small><small><br>
</small><small>- age 1: 26189384 bytes, 26189384 total</small><small><br>
</small><small>- age 2: 1713728 bytes, 27903112 total</small><small><br>
</small><small>: 882686K->34449K(943744K), 0.1280202 secs]
20030826K->19182589K(50226816K), 0.1285927 secs] [Times:
user=3.94 sys=0.01, real=0.13 secs]</small><small><br>
</small><small>Heap after GC invocations=11133 (full 166):</small><small><br>
</small><small>par new generation total 943744K, used 34449K
[0xfffffff353c00000, 0xfffffff393c00000, 0xfffffff393c00000)</small><small><br>
</small><small>eden space 838912K, 0% used
[0xfffffff353c00000, 0xfffffff353c00000, 0xfffffff386f40000)</small><small><br>
</small><small>from space 104832K, 32% used
[0xfffffff38d5a0000, 0xfffffff38f744468, 0xfffffff393c00000)</small><small><br>
</small><small>to space 104832K, 0% used [0xfffffff386f40000,
0xfffffff386f40000, 0xfffffff38d5a0000)</small><small><br>
</small><small>concurrent mark-sweep generation total
49283072K, used 19148140K [0xfffffff393c00000,
0xffffffff53c00000, 0xffffffff53c00000)</small><small><br>
</small><small>concurrent-mark-sweep perm gen total 524288K,
used 44308K [0xffffffff53c00000, 0xffffffff73c00000,
0xffffffff73c00000)</small><small><br>
</small><small>}</small><small><br>
</small><small>Total time for which application threads were
stopped: 0.1370098 seconds</small><small><br>
</small><small>Application time: 53.6273550 seconds</small><small><br>
</small><small>Total time for which application threads were
stopped: 0.0429426 seconds</small><small><br>
</small><small>Application time: 0.0002318 seconds</small><small><br>
</small><small>Total time for which application threads were
stopped: 0.0044294 seconds</small><small><br>
</small><small>Application time: 0.0002250 seconds</small><small><br>
</small><small>Total time for which application threads were
stopped: 0.0016478 seconds</small><small><br>
</small><small>Application time: 59.0926108 seconds</small><small><br>
</small><small>Total time for which application threads were
stopped: 0.0431387 seconds</small><small><br>
</small><small>Application time: 0.0002193 seconds</small><small><br>
</small><small>Total time for which application threads were
stopped: 0.0020966 seconds</small><small><br>
</small><small>Application time: 0.0000956 seconds</small><small><br>
</small><small>Total time for which application threads were
stopped: 0.0016358 seconds</small><small><br>
</small><small>Application time: 60.1048190 seconds</small><small><br>
</small><small>Total time for which application threads were
stopped: 0.0481582 seconds</small><small><br>
</small><small>Application time: 0.0002207 seconds</small><small><br>
</small><small>Total time for which application threads were
stopped: 0.0067752 seconds</small><small><br>
</small><small>Application time: 0.0001073 seconds</small><small><br>
</small><small>Total time for which application threads were
stopped: 0.0016387 seconds</small><small><br>
</small><small>Application time: 60.7453974 seconds</small><small><br>
</small><small>Total time for which application threads were
stopped: 0.0425995 seconds</small><small><br>
</small><small>Application time: 0.0002457 seconds</small><small><br>
</small><small>Total time for which application threads were
stopped: 0.0019724 seconds</small><small><br>
</small><small>Application time: 0.0001005 seconds</small><small><br>
</small><small>Total time for which application threads were
stopped: 0.0016210 seconds</small><small><br>
</small><small>Application time: 59.0845530 seconds</small><small><br>
</small><small>Total time for which application threads were
stopped: 0.0424095 seconds</small><small><br>
</small><small>Application time: 0.0002314 seconds</small><small><br>
</small><small>Total time for which application threads were
stopped: 0.0020107 seconds</small><small><br>
</small><small>Application time: 0.0000959 seconds</small><small><br>
</small><small>Total time for which application threads were
stopped: 0.0015940 seconds</small><small><br>
</small><small>Application time: 60.7994458 seconds</small><small><br>
</small><small>Total time for which application threads were
stopped: 0.0428210 seconds</small><small><br>
</small><small>Application time: 0.0002210 seconds</small><small><br>
</small><small>Total time for which application threads were
stopped: 0.0020541 seconds</small><small><br>
</small><small>Application time: 0.0000974 seconds</small><small><br>
</small><small>Total time for which application threads were
stopped: 0.0016126 seconds</small><small><br>
</small><small>Application time: 59.0963098 seconds</small><small><br>
</small><small>Total time for which application threads were
stopped: 0.0592795 seconds</small><small><br>
</small><small>Application time: 0.0002622 seconds</small><small><br>
</small><small>Total time for which application threads were
stopped: 0.0023229 seconds</small><small><br>
</small><small>Application time: 0.0000926 seconds</small><small><br>
</small><small>Total time for which application threads were
stopped: 0.0016296 seconds</small><small><br>
</small><small>Application time: 60.1021141 seconds</small><small><br>
</small><small>Total time for which application threads were
stopped: 0.0443986 seconds</small><small><br>
</small><small>Application time: 0.0002462 seconds</small><small><br>
</small><small>Total time for which application threads were
stopped: 0.0021135 seconds</small><small><br>
</small><small>Application time: 0.0001076 seconds</small><small><br>
</small><small>Total time for which application threads were
stopped: 0.0016165 seconds</small><small><br>
</small><small>Application time: 60.0324234 seconds</small><small><br>
</small><small>Total time for which application threads were
stopped: 0.0437486 seconds</small><small><br>
</small><small>Application time: 0.0002286 seconds</small><small><br>
</small><small>Total time for which application threads were
stopped: 0.0021017 seconds</small><small><br>
</small><small>Application time: 0.0001073 seconds</small><small><br>
</small><small>Total time for which application threads were
stopped: 0.0016570 seconds</small><small><br>
</small><small>Application time: 60.4613330 seconds</small><small><br>
</small><small>Total time for which application threads were
stopped: 0.0490276 seconds</small><small><br>
</small><small>Application time: 0.0002947 seconds</small><small><br>
</small><small>Total time for which application threads were
stopped: 0.0024618 seconds</small><small><br>
</small><small>Application time: 0.0001238 seconds</small><small><br>
</small><small>Total time for which application threads were
stopped: 0.0019863 seconds</small><small><br>
</small><small>Application time: 59.8201422 seconds</small><small><br>
</small><small>Total time for which application threads were
stopped: 0.0455540 seconds</small><small><br>
</small><small>Application time: 0.0003668 seconds</small><small><br>
</small><small>Total time for which application threads were
stopped: 0.0020906 seconds</small><small><br>
</small><small>Application time: 0.0001126 seconds</small><small><br>
</small><small>Total time for which application threads were
stopped: 0.0016693 seconds</small><small><br>
</small><small>Application time: 60.0721521 seconds</small><small><br>
</small><small>Total time for which application threads were
stopped: 0.0438111 seconds</small><small><br>
</small><small>Application time: 0.0002660 seconds</small><small><br>
</small><small>Total time for which application threads were
stopped: 0.0019814 seconds</small><small><br>
</small><small>Application time: 0.0001018 seconds</small><small><br>
</small><small>Total time for which application threads were
stopped: 0.0017817 seconds</small><small><br>
</small><small>Application time: 60.0825886 seconds</small><small><br>
</small><small>Total time for which application threads were
stopped: 0.0440386 seconds</small><small><br>
</small><small>Application time: 0.0002197 seconds</small><small><br>
</small><small>Total time for which application threads were
stopped: 0.0020655 seconds</small><small><br>
</small><small>Application time: 0.0001093 seconds</small><small><br>
</small><small>Total time for which application threads were
stopped: 0.0016122 seconds</small><small><br>
</small><small>Application time: 59.6628580 seconds</small><small><br>
</small><small>Total time for which application threads were
stopped: 0.0425082 seconds</small><small><br>
</small><small>Application time: 0.0002121 seconds</small><small><br>
</small><small>Total time for which application threads were
stopped: 0.0020967 seconds</small><small><br>
</small><small>Application time: 0.0000935 seconds</small><small><br>
</small><small>Total time for which application threads were
stopped: 0.0015909 seconds</small><small><br>
</small><small>Application time: 60.1951548 seconds</small><small><br>
</small><small>Total time for which application threads were
stopped: 0.0432125 seconds</small><small><br>
</small><small>Application time: 0.0002274 seconds</small><small><br>
</small><small>Total time for which application threads were
stopped: 0.0020316 seconds</small><small><br>
</small><small>Application time: 0.0001062 seconds</small><small><br>
</small><small>Total time for which application threads were
stopped: 0.0016534 seconds</small><small><br>
</small><small>Application time: 59.5329171 seconds</small><small><br>
</small></font><font face="'Consolas',monospace"><strong><font
color="#ff0000">Total time for which application threads
were stopped: 20.6893643 seconds</font></strong></font><font
face="'Consolas',monospace"><small><br>
</small><small>Application time: 0.0002839 seconds</small><small><br>
</small><small>Total time for which application threads were
stopped: 0.0076240 seconds</small><small><br>
</small><small>Application time: 0.0002137 seconds</small><small><br>
</small><small>Total time for which application threads were
stopped: 0.0019918 seconds</small><small><br>
</small><small>Application time: 39.4376656 seconds</small><small><br>
</small><small>Total time for which application threads were
stopped: 0.0612671 seconds</small><small><br>
</small><small>Application time: 0.0002478 seconds</small></font><br>
</div>
<div><br>
</div>
<div>Any idea ?<br>
<br>
<br>
Thanks in advance for your help<br>
-- <br>
David Tavoularis<br>
</div>
<div><br>
</div>
<div><br>
</div>
<div><br>
</div>
<div><br>
</div>
<div><br>
</div>
<div><br>
</div>
<div>[Annex]<br>
Complete GC log file gc_201108232207.log.gz available here: <a
moz-do-not-send="true" href="http://dl.free.fr/gxrxlLsVS">
http://dl.free.fr/gxrxlLsVS</a><br>
<br>
JVM command line extract :<br>
<font face="'Consolas',monospace"><small>/usr/jdk/instances/jdk1.6.0/jre/bin/sparcv9/java
-Dsun.rmi.dgc.checkInterval=2000 -server -Xms49152m
-Xmx49152m -XX:PermSize=512m -XX:+UseConcMarkSweepGC
-XX:+UseParNewGC -XX:+DisableExplicitGC
-XX:-CMSParallelRemarkEnabled
-XX:CMSInitiatingOccupancyFraction=40 -XX:NewSize=1024m
-XX:MaxNewSize=1024m -XX:+PrintGCDetails
-XX:+PrintGCTimeStamps -XX:+PrintHeapAtGC
-XX:+PrintTenuringDistribution
-XX:+PrintGCApplicationStoppedTime
-XX:+PrintGCApplicationConcurrentTime -XX:+PrintGCDateStamps
-Xloggc:/logs/gc_201108232207.log -XX:+UseCompressedOops
-XX:+HeapDumpOnOutOfMemoryError
-XX:HeapDumpPath=/data/heapdump</small></font><br>
<br>
<font face="'Consolas',monospace"><small><strong>$
/usr/jdk/instances/jdk1.6.0/jre/bin/sparcv9/java -version</strong></small><small><br>
</small><small>java version "1.6.0_25"</small><small><br>
</small><small>Java(TM) SE Runtime Environment (build
1.6.0_25-b06)</small><small><br>
</small><small>Java HotSpot(TM) 64-Bit Server VM (build
20.0-b11, mixed mode)</small><small><br>
</small><small><br>
</small><small><strong>$ /usr/sbin/prtdiag | head -3</strong></small><small><br>
</small><small>System Configuration: Sun Microsystems sun4u
Sun Fire E6900</small><small><br>
</small><small>System clock frequency: 150 MHz</small><small><br>
</small><small>Memory size: 143360 Megabytes</small><small><br>
</small><small><br>
</small><small><strong>$ mpstat | wc -l</strong></small><small><br>
</small><small>49</small><small><br>
</small><small><br>
</small><small><strong>$ uname -a</strong></small><small><br>
</small><small>SunOS XXX 5.9 Generic_122300-05 sun4u sparc
SUNW,Sun-Fire</small></font><br>
<br>
For your information, Full GC automatically triggered at 2:30am
:<br>
<strong><font face="'Consolas',monospace"><small>$ grep Full
gc_201108232207.log</small></font></strong><br>
<font face="'Consolas',monospace"><small>2011-08-24T02:30:02.475+0100:
15737.603: [Full GC 15737.604: [CMS:
11972490K->5028118K(49283072K), 137.9859661 secs]
12141664K->5028118K(50226816K), [CMS Perm :
39558K->39491K(524288K)], 137.9867010 secs] [Times:
user=133.02 sys=4.89, real=137.99 secs]</small><small><br>
</small><small>2011-08-25T02:30:05.142+0100: 102139.150: [Full
GC 102139.150: [CMS: 18724122K->11970549K(49283072K),
433.4189517 secs] 18976948K->11970549K(50226816K), [CMS
Perm : 44256K->42995K(524288K)], 433.4350620 secs]
[Times: user=429.00 sys=3.89, real=433.44 secs]</small><small><br>
</small><small>2011-08-26T02:30:05.125+0100: 188538.009: [Full
GC 188538.009: [CMS: 15865994K->12528867K(49283072K),
477.0168566 secs] 16343213K->12528867K(50226816K), [CMS
Perm : 44324K->43408K(524288K)], 477.0175358 secs]
[Times: user=476.76 sys=0.05, real=477.02 secs]</small><small><br>
</small><small>2011-08-27T02:30:03.084+0100: 274934.847: [Full
GC 274934.849: [CMS: 14857264K->8811922K(49283072K),
312.4786042 secs] 15546860K->8811922K(50226816K), [CMS
Perm : 44557K->43762K(524288K)], 312.4796506 secs]
[Times: user=312.38 sys=0.11, real=312.48 secs]</small><small><br>
</small><small>2011-08-28T02:30:04.129+0100: 361334.770: [Full
GC 361334.777: [CMS: 16479144K->5767617K(49283072K),
161.5857103 secs] 17318705K->5767617K(50226816K), [CMS
Perm : 44127K->43481K(524288K)], 161.5863909 secs]
[Times: user=161.21 sys=0.02, real=161.59 secs]</small><small><br>
</small><small>2011-08-29T02:30:03.316+0100: 447732.838: [Full
GC 447732.838: [CMS: 13471208K->6989798K(49283072K),
173.7255263 secs] 13700543K->6989798K(50226816K), [CMS
Perm : 43709K->43433K(524288K)], 173.7260186 secs]
[Times: user=173.48 sys=0.01, real=173.73 secs]</small></font><br>
<br>
</div>
<br>
<hr>
<font color="Gray" face="Arial" size="1"><br>
This electronic message contains information from Mycom which
may be privileged or confidential. The information is intended
to be for the use of the individual(s) or entity named above. If
you are not the intended recipient, be aware that any
disclosure, copying, distribution or any other use of the
contents of this information is prohibited. If you have received
this electronic message in error, please notify us by post or
telephone (to the numbers or correspondence address above) or by
email (at the email address above) immediately.<br>
</font>
<pre wrap="">
<fieldset class="mimeAttachmentHeader"></fieldset>
_______________________________________________
hotspot-gc-use mailing list
<a class="moz-txt-link-abbreviated" href="mailto:hotspot-gc-use@openjdk.java.net">hotspot-gc-use@openjdk.java.net</a>
<a class="moz-txt-link-freetext" href="http://mail.openjdk.java.net/mailman/listinfo/hotspot-gc-use">http://mail.openjdk.java.net/mailman/listinfo/hotspot-gc-use</a>
</pre>
</blockquote>
</body>
</html>