You are viewing a plain text version of this content. The canonical link for it is here.
Posted to users@tomcat.apache.org by Ken Bowen <kb...@als.com> on 2010/03/24 14:31:55 UTC
GC behavior elucidation
Hi all,
I've been working on the memory behavior of a small Tomcat 6.0.20/Java
1.6 app running in constrained space (288MB total on a VPS running
CentOS 5). Earlier advice from the list enabled me to track down the
most glaring culprit memory leaks. The app is currently lightly used,
but even under light use earlier, it was growing out of bounds.
This message is a question about types of GC behavior. I've been
monitoring the app using GC logging and dumping a lot of info to
catalina out. I've seen three distinct types of GCs. I understand
the Full GC and "routine" GC, but I'm not sure I understand the third
type.
My gclog shows routine GCs approx every 3-4 mins that look like this:
2010-03-17T01:28:05.888-0400: 543717.992: [GC 543717.992: [DefNew:
6222K->487K(6528K), 0.0030010 secs] 44060K->38706K(64832K), 0.0030920
secs] [Times: user=0.01 sys=0.00, real=0.01 secs]
Since 3/10, I've seen 5 Full GCs
03-11T05:23
03-11T15:00
03-11T19:49
03-12T00:09
03-17T01:07
looking like this last one:
2010-03-17T01:07:34.278-0400: 542486.382: [Full GC 542486.382:
[Tenured: 58226K->35935K(58304K), 0.1316550 secs] 64221K-
>35935K(64832K), [Perm : 21200K->21200K(21248K)], 0.1317440 secs]
[Times: user=0.13 sys=0.00, real=0.13 secs]
At the same time, catalina.out shows a lot of entries like this:
INFO | jvm 1 | 2010/03/17 01:07:34 | [Unloading class
sun.reflect.GeneratedMethodAccessor233]
I've seen 7 GCs of the third type:
03-11T00:11
03-11T10:12
03-11T15:00
03-12T04:23
03-12T08:33
03-21T03:44
03-23T20:44
looking like this one last night:
2010-03-23T20:44:55.835-0400: 1131527.939: [GC 1131527.939: [DefNew
(promotion failed): 6205K->5999K(6528K), 0.0047690 secs]1131527.944:
[Tenured: 58304K->36397K(58304K), 0.1396970 secs] 64399K-
>36397K(64832K), [Perm : 21631K->21631K(21760K)], 0.1446100 secs]
[Times: user=0.14 sys=0.00, real=0.14 secs]
Just like the Full GCs, catalina.out shows lots of these entries:
INFO | jvm 1 | 2010/03/23 20:44:55 | [Unloading class
sun.reflect.GeneratedMethodAccessor360]
Finally, last night I happened to notice that top was showing tomcat %
was 44, while this morning was 43.5, which of course is nice to see :-).
I assume that the third type of GC is something intermediate between
the routine (every 4 mins) small collection and a Full GC. Can anyone
describe it to me or point me to some GC doc describing the details.
Many thanks,
Ken
---------------------------------------------------------------------
To unsubscribe, e-mail: users-unsubscribe@tomcat.apache.org
For additional commands, e-mail: users-help@tomcat.apache.org
Re: GC behavior elucidation
Posted by Ken Bowen <kb...@als.com>.
Chuck....thanks....Ken
On Mar 24, 2010, at 9:51 AM, Caldarale, Charles R wrote:
>> From: Ken Bowen [mailto:kbowen@als.com]
>> Subject: GC behavior elucidation
>>
>> My gclog shows routine GCs approx every 3-4 mins that look like this:
>> 2010-03-17T01:28:05.888-0400: 543717.992:
>> [GC 543717.992:
>> [DefNew: 6222K->487K(6528K), 0.0030010 secs]
>> 44060K->38706K(64832K), 0.0030920 secs]
>> [Times: user=0.01 sys=0.00, real=0.01 secs]
>
> Looks reasonable. Make sure the contracted number stay about where
> they are; if they keep increasing, you've still got a leak.
>
>> Since 3/10, I've seen 5 Full GCs
>> 2010-03-17T01:07:34.278-0400: 542486.382:
>> [Full GC 542486.382:
>> [Tenured: 58226K->35935K(58304K), 0.1316550 secs]
>> 64221K->35935K(64832K),
>> [Perm : 21200K->21200K(21248K)],
>> 0.1317440 secs]
>> [Times: user=0.13 sys=0.00, real=0.13 secs]
>>
>> At the same time, catalina.out shows a lot of entries like this:
>> INFO | jvm 1 | 2010/03/17 01:07:34 | [Unloading class
>> sun.reflect.GeneratedMethodAccessor233]
>
> Normal for a full GC - unused classes are being discarded.
>
>> I've seen 7 GCs of the third type:
>> 2010-03-23T20:44:55.835-0400: 1131527.939:
>> [GC 1131527.939:
>> [DefNew (promotion failed): 6205K->5999K(6528K), 0.0047690 secs]
>> 1131527.944:
>> [Tenured: 58304K->36397K(58304K), 0.1396970 secs]
>> 64399K->36397K(64832K),
>> [Perm : 21631K->21631K(21760K)],
>> 0.1446100 secs]
>> [Times: user=0.14 sys=0.00, real=0.14 secs]
>
>> I assume that the third type of GC is something intermediate between
>> the routine (every 4 mins) small collection and a Full GC.
>
> No, it's a minor collection that turned into a major one due to the
> tenured space being full. If you haven't prevented internal heap
> component resizing via command-line settings, the JVM will try to
> adjust the sizes of the spaces to try to avoid reoccurrence.
> However, your tenured usage seems to be creeping up, so you may well
> still have a leak.
>
> - Chuck
>
>
> THIS COMMUNICATION MAY CONTAIN CONFIDENTIAL AND/OR OTHERWISE
> PROPRIETARY MATERIAL and is thus for use only by the intended
> recipient. If you received this in error, please contact the sender
> and delete the e-mail and its attachments from all computers.
>
>
> ---------------------------------------------------------------------
> To unsubscribe, e-mail: users-unsubscribe@tomcat.apache.org
> For additional commands, e-mail: users-help@tomcat.apache.org
>
---------------------------------------------------------------------
To unsubscribe, e-mail: users-unsubscribe@tomcat.apache.org
For additional commands, e-mail: users-help@tomcat.apache.org
RE: GC behavior elucidation
Posted by "Caldarale, Charles R" <Ch...@unisys.com>.
> From: Ken Bowen [mailto:kbowen@als.com]
> Subject: GC behavior elucidation
>
> My gclog shows routine GCs approx every 3-4 mins that look like this:
> 2010-03-17T01:28:05.888-0400: 543717.992:
> [GC 543717.992:
> [DefNew: 6222K->487K(6528K), 0.0030010 secs]
> 44060K->38706K(64832K), 0.0030920 secs]
> [Times: user=0.01 sys=0.00, real=0.01 secs]
Looks reasonable. Make sure the contracted number stay about where they are; if they keep increasing, you've still got a leak.
> Since 3/10, I've seen 5 Full GCs
> 2010-03-17T01:07:34.278-0400: 542486.382:
> [Full GC 542486.382:
> [Tenured: 58226K->35935K(58304K), 0.1316550 secs]
> 64221K->35935K(64832K),
> [Perm : 21200K->21200K(21248K)],
> 0.1317440 secs]
> [Times: user=0.13 sys=0.00, real=0.13 secs]
>
> At the same time, catalina.out shows a lot of entries like this:
> INFO | jvm 1 | 2010/03/17 01:07:34 | [Unloading class
> sun.reflect.GeneratedMethodAccessor233]
Normal for a full GC - unused classes are being discarded.
> I've seen 7 GCs of the third type:
> 2010-03-23T20:44:55.835-0400: 1131527.939:
> [GC 1131527.939:
> [DefNew (promotion failed): 6205K->5999K(6528K), 0.0047690 secs]
> 1131527.944:
> [Tenured: 58304K->36397K(58304K), 0.1396970 secs]
> 64399K->36397K(64832K),
> [Perm : 21631K->21631K(21760K)],
> 0.1446100 secs]
> [Times: user=0.14 sys=0.00, real=0.14 secs]
> I assume that the third type of GC is something intermediate between
> the routine (every 4 mins) small collection and a Full GC.
No, it's a minor collection that turned into a major one due to the tenured space being full. If you haven't prevented internal heap component resizing via command-line settings, the JVM will try to adjust the sizes of the spaces to try to avoid reoccurrence. However, your tenured usage seems to be creeping up, so you may well still have a leak.
- Chuck
THIS COMMUNICATION MAY CONTAIN CONFIDENTIAL AND/OR OTHERWISE PROPRIETARY MATERIAL and is thus for use only by the intended recipient. If you received this in error, please contact the sender and delete the e-mail and its attachments from all computers.
---------------------------------------------------------------------
To unsubscribe, e-mail: users-unsubscribe@tomcat.apache.org
For additional commands, e-mail: users-help@tomcat.apache.org