What does <AF> mean and how do I know if my WebApp does GC too oftenor not

[Li Ma]

Dear all,

it might be a question asked by millions of people already, but I ran
into this situation recently and really did not find any good answer
by Googling. So please bear with me.

Out Web App(IBM AIX with 32G RAM, JVM has 8G heap) used to do GC every
20 minutes before. This week, we rolled it out to more users and
traffic pretty doubled. Now GC happens every 5 minutes.

When I looked at GC log, most of them are AF tags like:

<af type="tenured" id="23" timestamp="Mar 04 11:15:32 2009"
intervalms="306716.943">
<minimum requested_bytes="40" />
<time exclusiveaccessms="0.138" />
<tenured freebytes="0" totalbytes="4294967296" percent="0" >
<soa freebytes="0" totalbytes="4294967296" percent="0" />
<loa freebytes="0" totalbytes="0" percent="0" />
</tenured>
<gc type="global" id="23" totalid="23" intervalms="306718.278">
<classloadersunloaded count="0" timetakenms="13.917" />
<refs_cleared soft="337" threshold="32" weak="20751"
phantom="146" />
<finalization objectsqueued="14809" />
<timesms mark="310.258" sweep="29.900" compact="0.000"
total="355.879" />
<tenured freebytes="3954711744" totalbytes="4294967296"
percent="92" >
<soa freebytes="3954711744" totalbytes="4294967296"
percent="92" />
<loa freebytes="0" totalbytes="0" percent="0" />
</tenured>
<soa freebytes="3954710192" totalbytes="4294967296" percent="92" / <loa freebytes="0" totalbytes="0" percent="0" />
</tenured>
<time totalms="357.344" />
</af>

In my team, people are arguing GC every 5 minutes is healthy. AF,
although is called Allocation failure, is also not a problem.

But my feeling is that the WebApp is over utilizing objects, therefore
it eats up heap too quick (4G in 5 minutes). That's why so many AF
logs are created.

So my questions are:
1. Is AF GC every 5 minutes healthy? We are expecting more load on the
web app soon. So it could go down to AF GC every 1 minute soon.
2. For a machine with 8G heap allocated to JVM, only serving about
2000 users, how frequently should we expect the GC to happen?

And if you have any other comment or finding on the GC log, please
please share with me.

Thank you very much!

Li

 

[Roedy Green]

Out Web App(IBM AIX with 32G RAM, JVM has 8G heap) used to do GC every
20 minutes before. This week, we rolled it out to more users and
traffic pretty doubled. Now GC happens every 5 minutes.

Wow. It must be wonderful to have so much RAM. I get GCs at least once
a minute on most of my apps.

What could make the frequency of GC go up?

1. More traffic. In testing you will have light traffic. In the real
world, your app can get a real workout. You are creating more objects
per second.

2. different default heap size.

3. Something clever in the JVM that looks at REAL ram available and
effectively shrinks the heap when other apps are eating up all the
RAM.

4. If you were using Jet with an adaptive heap that grows and shrinks
as the app runs depending on how much REAL ram is free in the system,
other apps and the amount of physical ram will affect how often GC
occurs.

5. In the real application perhaps there are some large objects. This
effectively shrinks your heap, causing more frequent GC.

6. to find out what is going on, profile. See
http://mindprod.com/jgloss/profiler.html
--
Roedy Green Canadian Mind Products
http://mindprod.com

"Pollution is nothing but the resources we are not harvesting. We allow them to disperse because we’ve been ignorant of their value."
~ Richard Buckminster (Bucky) Fuller